Issue with Jellyfin Import when playing media

[FoMoCo53]

Hi,

I have been doing some investigation into an issue I have been having and what I have worked out is if the import process is run whilst I am playing a file in Jellyfin it will cause the status of the file to become invalid.

I have a Plex and Jellyfin running and have Watchstate set to run via cron every hour. Import 0 * and export 5 *. Which if Jellyfin is not playing a file works fine and I have no issues. However if I am playing something in Jellyfin when the import job runs that is when it gets all screwed up.

During investigating the issues, I discovered that Jellyfin had wrong metadata on a bunch of files which caused WS to keep importing the the same files again and again. So I kept running the Metadata only import until I fixed all the errors and it wasnt importing any new data. aka removed all the duplicates etc.

After doing this I was still randomly getting files that didnt import correctly. And after going through the app*.log I suspected the issue and changed the cron job to run at 0100 only. And it seems to be fine

Below are extracts from the app*.log let me know if you need more info
I cant say exactly when I started to watch or finished watching this particular file, and I couldnt work out what the progress number meant. But happy to do further testing if it helps

This is the first entry of this file in the log, I suspect this was whilst I was watching it

[2024-03-13T18:00:30.824867+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x005] due to play progress change. {"id":13888,"changes":{"metadata":{"jellyfin":{"progress":{"old":"0","new":"650268"}}}},"fields":"metadata"} []

This looks to be next import run and it seems to have marked it as watched, but if I am working this out it correctly has marked it as watch at 2024-03-13 17:51:21, which is before the previous import job ran. It is almost like Jellyfin is marking the file as watched at the time I started watching it?

[2024-03-13T19:01:14.423510+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x005] due to play progress change. {"id":13888,"changes":{"metadata":{"jellyfin":{"watched":{"old":"0","new":"1"},"progress":{"old":"650268","new":"0"},"played_at":{"old":"None","new":"1710312681"}}}},"fields":"metadata"} []

This is then the next time the import ran and the file is now in an invalid state. It stays like this until I manually fix it. I was originally just marking it as played in Plex, but then I tested marking it as unplayed then played in Jellyfin and this also fixes it, as it updates the watched date to valid one.

[2024-03-13T20:00:56.476052+11:00] logger.NOTICE: MAPPER: [jellyfin] item [13888: Ray Donovan (2014) - 02x005] is marked as [played] vs local state [unplayed], However due the remote item date [2024-03-13T17:51:21+11:00] being older than the last backend sync date [2024-03-13T19:00:48+11:00]. it was not considered as valid state. [] []

Let me know if you want more information or testing done.

Thanks Heaps for all your work
FoMoCo

[arabcoders]

Thanks, This seems to be an issue with jellyfin backend when the media is being played. i thought i marked the event as tainted as such it shouldn't trigger mark as watched, However. I'll have to dig into it, in the meantime, try using the webhooks for updating and see if it fixes the issue for you.

[arabcoders]

@FoMoCo53 , i think I've traced the issue, Please try ghcr.io/arabcoders/watchstate:dev branch and see if it fixes your problem.

[arabcoders]

The fix has been applied to latest branch, feel free to test it.

[FoMoCo53]

Hi,

I just finished running a test on the :dev branch and it is doing the same thing.

[2024-03-16T08:58:36.233394+11:00] logger.NOTICE: MAPPER: [jellyfin] item [13891: Ray Donovan (2014) - 02x008] is marked as [played] vs local state [unplayed], However due the remote item date [2024-03-16T08:10:36+11:00] being older than the last backend sync date [2024-03-16T08:57:14+11:00]. it was not considered as valid state. [] []

docker exec -ti watchstate console -V
WatchState 20240315-cb4d493

I took note of the time that I started watching the episode and that is the time that the episode is being marked as played at. Not the time that I actually finished watching the episode. This seems wrong on the behalf of Jellyfin and makes no sense why it is marking the played at time the time you started watching it. Correct me if I am wrong, but I suspect that is what is causing the issue.

Thanks again

FoMoCo

[FoMoCo53]

That was using the existing data, I just changed the branch on the existing container and ran an import export

Do you want me to try with a new DB? If so what is the best way to do so?

[arabcoders]

You try with completely new data remove the ./data folder and start a new

This is the best way to ensure test data integrity.

[FoMoCo53]

I suspected that might be the case.
Ill change to the :latest branch, run through the setup, run a test and let you know how it goes

[FoMoCo53]

Running through the setup of plex and got this error

Would you like to import play state & metadata from the backend now? [Y|N] [Default: No]
-----------------
P.S: this could take few minutes to execute.

> y
Importing play state & metadata from plex

In ImportCommand.php line 255:

  count(): Argument #1 ($value) must be of type Countable|array, string given


config:add [-s|--select-backend SELECT-BACKEND]

ill run a manual import for now

[arabcoders]

Indeed it seems i forgot to update this code when we changed how we handle some arguments. No worries you can safely ignore this error and do the manual import.

[FoMoCo53]

I just ran another test after doing a fresh setup and it is still doing the same thing

Started playing at 11:07

A few minutes into playing

console state:import -v
[2024-03-16T11:16:03.792997+11:00] logger.NOTICE: Using WatchState Version - '20240315-2dd9c08'. [] []
[2024-03-16T11:16:30.830957+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x009] due to play progress change. {"id":13903,"changes":{"metadata":{"jellyfin":{"watched":{"old":"0","new":0},"progress":{"old":"0","new":"490345"}}}},"fields":"metadata"} []

Finished playing

console state:import -v
[2024-03-16T11:52:49.782488+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x009] due to play progress change. {"id":13903,"changes":{"metadata":{"jellyfin":{"watched":{"old":"0","new":0},"progress":{"old":"490345","new":"0"},"played_at":{"old":"None","new":"1710547631"}}}},"fields":"metadata"} []

Re Ran

console state:import -v
[2024-03-16T11:55:04.522467+11:00] logger.NOTICE: MAPPER: [jellyfin] item [13903: Ray Donovan (2014) - 02x009] is marked as [played] vs local state [unplayed], However due the remote item date [2024-03-16T11:07:11+11:00] being older than the last backend sync date [2024-03-16T11:52:24+11:00]. it was not considered as valid state. [] []

FoMoCo

[arabcoders]

Thank you for confirming the issue. I believe i might have noticed the issue. Hopefully will have a fix tomorrow. In the meantime could you run system:report for me and post the results.

[FoMoCo53]

Thanks again for looking into it here is the report minus the plex keys

[ Basic Report ]

WatchState Version: 20240315-2dd9c08
PHP Version: 8.2.17
Timezone: Australia/Sydney
Running in Container? Yes
Data Path: /config
Temp Path: /config
Database Migrated?: Yes
Has .env file? No
Is Tasks Runner working? Yes
Report Generated At: 2024-03-16T01:04:26+00:00

[ Backends ]

[ Plex ==> plex ]

Is backend URL HTTPS? Yes
Has Unique Identifier? Yes
Has User? Yes
Export Enabled? Yes
Time since last export? 2024-03-16T00:04:22+00:00
Play state import enabled? Yes
Metadata only import enabled? No
Time since last import? 2024-03-16T00:54:39+00:00
Has webhook token? Yes
Is webhook match user id enabled? Yes
Is webhook match backend unique id enabled? Yes
Has custom options? Yes
{"plex_user_uuid":"xxxxxxx","ADMIN_TOKEN":"xxxxxxx"}
[ Jellyfin ==> jellyfin ]

Is backend URL HTTPS? Yes
Has Unique Identifier? Yes
Has User? Yes
Export Enabled? Yes
Time since last export? 2024-03-16T00:04:22+00:00
Play state import enabled? Yes
Metadata only import enabled? No
Time since last import? 2024-03-16T00:54:39+00:00
Has webhook token? Yes
Is webhook match user id enabled? No
Is webhook match backend unique id enabled? Yes
Has custom options? No
{}
[ Tasks ]

[ Import ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 1 * * *
When is the next scheduled run? 2024-03-16T05:00:00+00:00

[ Export ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 5 1 * * *
When is the next scheduled run? 2024-03-16T05:05:00+00:00

[ Push ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? */10 * * * *
When is the next scheduled run? 2024-03-16T01:10:00+00:00

[ Progress ]

Is Task enabled? No

[ Backup ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 6 */3 * *
When is the next scheduled run? 2024-03-18T19:00:00+00:00

[ Prune ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 */12 * * *
When is the next scheduled run? 2024-03-16T13:00:00+00:00

[ Indexes ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 3 * * 3
When is the next scheduled run? 2024-03-19T16:00:00+00:00

[ Requests ]

Is Task enabled? Yes
Which flags are used to run the task? -v --no-stats
When the task scheduled to run at? */2 * * * *
When is the next scheduled run? 2024-03-16T01:06:00+00:00

[ Logs ]

[ /config/logs/app.20240316.log ]

[2024-03-16T11:52:56.000726+11:00] logger.NOTICE: SYSTEM: Found [14] updated objects. {"memory":{"now":"233.44M","peak":"311.64M"}} []
[2024-03-16T11:54:37.623872+11:00] logger.NOTICE: Using WatchState Version - '20240315-2dd9c08'. [] []
[2024-03-16T11:54:37.624983+11:00] logger.NOTICE: SYSTEM: Preloading MemoryMapper data. {"memory":{"now":"4.58M","peak":"4.60M"}} []
[2024-03-16T11:54:38.824991+11:00] logger.NOTICE: SYSTEM: Preloading MemoryMapper data is complete. {"memory":{"now":"231.81M","peak":"232.30M"}} []
[2024-03-16T11:54:38.827068+11:00] logger.NOTICE: SYSTEM: Importing [plex] METADATA & PLAY STATE changes. {"since":"2024-03-16 11:52:24 AEDT"} []
[2024-03-16T11:54:39.591826+11:00] logger.NOTICE: SYSTEM: Importing [jellyfin] METADATA & PLAY STATE changes. {"since":"2024-03-16 11:52:24 AEDT"} []
[2024-03-16T11:54:39.657161+11:00] logger.NOTICE: SYSTEM: Waiting on [47] requests. {"time":{"start":"2024-03-16T11:54:39+11:00"},"memory":{"now":"234.03M","peak":"234.03M"}} []
[2024-03-16T11:55:04.522467+11:00] logger.NOTICE: MAPPER: [jellyfin] item [13903: Ray Donovan (2014) - 02x009] is marked as [played] vs local state [unplayed], However due the remote item date [2024-03-16T11:07:11+11:00] being older than the last backend sync date [2024-03-16T11:52:24+11:00]. it was not considered as valid state. [] []
[2024-03-16T11:55:10.672156+11:00] logger.NOTICE: SYSTEM: Finished waiting on [47] requests. {"time":{"start":"2024-03-16T11:54:39+11:00","end":"2024-03-16T11:55:10+11:00","duration":31},"memory":{"now":"233.44M","peak":"311.45M"},"responses":{"size":"61.40M"}} []
[2024-03-16T11:55:10.672660+11:00] logger.NOTICE: MAPPER: No changes detected. [] []

[ /config/logs/access.20240316.log ]

access log file is empty or does not exists.

[ /config/logs/task.20240316.log ]

task log file is empty or does not exists.

[ /config/logs/app.20240315.log ]

app log file is empty or does not exists.

[ /config/logs/access.20240315.log ]

access log file is empty or does not exists.

[ /config/logs/task.20240315.log ]

task log file is empty or does not exists.

[ Notice ]

Beware, while we try to make sure no sensitive information is leaked, it's possible
that some private information might be leaked via the logs section.
Please review the report before posting it.

[arabcoders]

I attempted to trigger the bug many times, it's just not triggering

i tried

• while playing
• while stopped
• while at the end

it's just not happening are you perhaps on jellyfin 10.9?

[arabcoders]

Nevermind, i was able to trigger the bug

[arabcoders]

Ok, After deep testing it seems, jellyfin does not update the UserData.LastPlayedDate when the item marked as played. And due to the way we handle item progress update via state:import it was causing conflict. Sadly there is no easy way to fix it with the current approach. Thus, i am forced to disable item progress update via state:import for jellyfin clients and rely solely on webhooks until such time i can re-write the logic handling for jellyfin or they fix the bug and update the LastPlayedDate correctly.

Thank you for your report and logs. I've pushed new build to dev which should be up for latest it will fix the issue temporary as described above.

[FoMoCo53]

Yeah I suspected something like that might be the case. Thanks for looking into it. Let me know if you want me to do more testing in the future.

[arabcoders]

Well.. this is embarrassing, i probably shouldn't do code updates when fasting lol. I think i truly fixed it now. I had the logic inversed.

I have pushed a fix, please do pull the dev branch and test when you can. try different episode

Thank you for your time.

[FoMoCo53]

Hi,

I just updated to the :dev branch and it is back to reporting the progress and still failing

Using WatchState Version - '20240318-bd1a7ab'.

Running the import whilst playing

[2024-03-19T08:20:32.800500+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x011] due to play progress change. {"id":13820,"changes":{"metadata":{"jellyfin":{"progress":{"old":"0","new":"266781"}}}},"fields":"metadata"} []

Running the import after playing

[2024-03-19T08:21:37.748498+11:00] logger.NOTICE: MAPPER: [jellyfin] updated [Ray Donovan (2014) - 02x011] due to play progress change. {"id":13820,"changes":{"metadata":{"jellyfin":{"watched":{"old":"0","new":"1"},"progress":{"old":"266781","new":"0"},"played_at":{"old":"None","new":"1710796795"}}}},"fields":"metadata"} []

Running the import again

[2024-03-19T08:22:15.165189+11:00] logger.NOTICE: MAPPER: [jellyfin] item [13820: Ray Donovan (2014) - 02x011] is marked as [played] vs local state [unplayed], However due the remote item date [2024-03-19T08:19:55+11:00] being older than the last backend sync date [2024-03-19T08:21:13+11:00]. it was not considered as valid state. [] []

[arabcoders]

Ok, Thank you for your update. It seems i really have to completely disable progress handling for jellyfin at all levels.

I'll get back to you hopefully tomorrow.

[arabcoders]

@FoMoCo53, Ok i had time to sit down and trace the issue, it's as you guessed, Jellyfin is not updating the date on object, which in turn confuses the importer, sadly there is nothing to fix as it's worked as intended.

However, I've implemented workaround for this issue which sadly only works via webhooks. Enable webhooks for jellyfin, and it should work as expected temporarily until someone raises an issue with jellyfin devs.

Please take a moment to test this and report back.