[Issue]: Jellyfin 10.9.1 Server unresponsive during and after some episodes

Arlind-dev commented 2 weeks ago

Please describe your bug

This issue doesn't occur every time, but while watching an episode with any client of my choice (tested: Jellyfin-web Chrome, JMP 1.10, Infuse, Jellyfin-web Firefox), my sessions get terminated. If my client isn't compatible with the source, the server stops transcoding. If it is compatible, it can't run the next episode because the server becomes unresponsive after the error appears.

Usually, it works normally until I encounter the following error:

[2024-05-16 08:16:45.579 +02:00] [ERR] [680] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request: "Unexpected end of request content". URL "POST" "/Sessions/Playing/Progress".

After that, I get this error:

[2024-05-16 08:16:45.713 +02:00] [ERR] [662] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request. URL "GET" "/Items/de140e6084afa708e32cd4c180bbc0a8/PlaybackInfo".
Microsoft.EntityFrameworkCore.DbUpdateConcurrencyException: The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded. See https://go.microsoft.com/fwlink/?LinkId=527962 for information on understanding and handling optimistic concurrency exceptions.

Then it completely terminates my session with these errors:

[2024-05-16 08:16:46.339 +02:00] [ERR] [564] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request: "Unexpected end of request content". URL "POST" "/Sessions/Playing/Progress".
[2024-05-16 08:16:46.340 +02:00] [ERR] [566] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request: "Unexpected end of request content". URL "POST" "/Sessions/Playing/Progress".
[2024-05-16 08:16:46.777 +02:00] [WRN] [507] jellyfin_ani_sync.UpdateProviderStatus: The user 3adcdd57-35d4-4cd6-8758-3f33e870afc2 does not exist in the plugins config file. Skipping
[2024-05-16 08:16:46.777 +02:00] [INF] [507] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Playback stop tracker found, processing stop: "830DADDC-DC97-49BE-A1D2-31E2C6E22FB1-3adcdd5735d44cd687583f33e870afc2-79c4e6cc4b1acc8be150be49de7ed9cf"
[2024-05-16 08:16:46.777 +02:00] [INF] [507] Jellyfin.Plugin.PlaybackReporting.Data.PlaybackTracker: PlaybackTracker: Adding Stop Event: 05/16/2024 08:16:46
[2024-05-16 08:16:46.777 +02:00] [INF] [507] Jellyfin.Plugin.PlaybackReporting.EventMonitorEntryPoint: Saving playback tracking activity in DB
[2024-05-16 08:17:17.836 +02:00] [WRN] [475] Emby.Server.Implementations.HttpServer.WebSocketConnection: WS "[My IP]" error receiving data: "The remote party closed the WebSocket connection without completing the close handshake."
[2024-05-16 08:17:17.840 +02:00] [INF] [475] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "[My IP]" closed

You can view the full logs here.

I saw the issue described in this https://github.com/jellyfin/jellyfin/issues/11624. According to the conclusion:

(If you think this is the same issue, you can close this)

We've found quite a bit of info in our internal chats about this (going through my core dumps and logs). The short version is, right now we're pretty sure the issue has to do with transcoding jobs and updating the transcode status. This happens very frequently, but there is a database query in there which is very heavy and after enough time the backlog locks everything up. That TP Worker is the process running the queries. We're working on a solution so please remain patient and we'll hopefully get that out in a 10.9.2 sometime very soon.

I'm not sure if I'm experiencing the same error.

~~Maybe important: This might be weird, but only I experience this error and not my friends, and the Webhook Plugin never creates an alert when I (the admin user) starts an episode. But it does for the other users.~~ Fixed and unrelated

Reproduction Steps

Watch an episode
Wait for the error

Jellyfin Version

10.9.0

if other:

10.9.1

Environment

- OS: Ubuntu 22.04.4 LTS x86_64
- Linux Kernel: 5.15.0-107-generic
- Virtualization: Docker
- Clients: Infuse, Jellyfin Mobile, Swiftfin, Web Chrome, Web Firefox (I tried all of them)
- Browser: Chrome & Firefox
- FFmpeg Version: ffmpeg version 6.0.1-Jellyfin
- Playback Method: Direct Play and HW Acceleration on and off
- Hardware Acceleration: tried with and without
- GPU Model: rtx 3050
- Plugins: Ani-Sync, AniDB- AniList, AniSearch, AudioDB, FanArt, InfuseSync (disabled), Kitsu, MusicBrainz, OMDb, Playback Reporting, Reports, Session Cleaner, Studio Images, Subtitle Extract, TMDb, TMDb Trailers, TVmaze, TheTVDB
- Reverse Proxy: Traefik
- Base URL: jellyfin.mydomain.tld
- Networking: Publish server Uri: jellyfin.mydomain.tld
- Storage: HDD

Jellyfin logs

https://pastebin.com/TqYwNDfH

FFmpeg logs

No response

Please attach any browser or client logs here

No response

Please attach any screenshots here

No response

Code of Conduct

[X] I agree to follow this project's Code of Conduct

jellyfin-bot commented 2 weeks ago

Hi, it seems like your issue report has the following item(s) that need to be addressed:

You have not filled in the environment completely.

This is an automated message, currently under testing. Please file an issue here if you encounter any problems.

idanoo commented 2 weeks ago

I'm seeing this too and it looks like SQLite is locking based on being spammed with this - Which almost confirms what your snippet says. Hoping it's an easy fix 🤞

[19:46:15] [ERR] [65] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request. URL POST /Sessions/Playing/Progress.
Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
   at Microsoft.Data.Sqlite.SqliteDataReader.NextResult()

Arlind-dev commented 2 weeks ago

I'm seeing this too and it looks like SQLite is locking based on being spammed with this - Which almost confirms what your snippet says. Hoping it's an easy fix 🤞
[19:46:15] [ERR] [65] Jellyfin.Api.Middleware.ExceptionMiddleware: Error processing request. URL POST /Sessions/Playing/Progress.
Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 5: 'database is locked'.
   at Microsoft.Data.Sqlite.SqliteDataReader.NextResult()

Interesting, though, I don't see anything about SQLite errors in my logs. I only see The database operation was expected to affect 1 row(s), but actually affected 0 row(s); data may have been modified or deleted since entities were loaded.