[Plugin Disabled] Issue with spamming Trakt API #174

rudf0rd · 2022-10-17T18:36:29Z

Note: This was fixed in v21 of the plugin, available for Jellyfin 10.8.5+

Original message:

Hey we've been tracking an issue on our API that an app is hammering the scrobble/start endpoint and concluded it's the Jellyfin plugin. We just revoked the Jellyfin API key and everything leveled out on the servers.

Can you guys help explain what's going on with the high frequency of scrobble/start calls? Please let us know how we can help get your plugin back online.

SenorSmartyPants · 2022-10-17T19:26:17Z

Is there a time window when you noticed the hammering start?

rudf0rd · 2022-10-17T19:32:30Z

It's somewhere in the vicinity of the end of August. It starts ramping up around 8/20. I am basing this guess on overall hits on the api endpoint and not specific to the Jellyfin api key, unfortunately.

Can you give me a basic scrobble flow for the plugin? As we dig in, we're noticing more than just the Jellyfin plugin are hitting the scrobble/start endpoint more than once during a play.

anthonylavado · 2022-10-17T19:39:08Z

@rudf0rd While SenorSmartyPants has contributed to this repo, they're not on the team proper. I believe our server and plugin folks are aware of this issue atm, I'm not sure when they'll have a moment to comment on the flow.

It's interesting to note if traffic ramps up as of Aug 20th. The last two releases of the plugin would have been Sep 2nd (version 20), and before that was May 28th (version 19). So nothing that directly lines up.

SenorSmartyPants · 2022-10-17T19:44:50Z

That's true I'm not on the team proper, but I thought it was a good question to ask. And I was curious to see if the time lined up with any changes I might have contributed so I could help fixing them.

Big Thanks to the JF and Trakt teams!

rudf0rd · 2022-10-17T19:50:46Z

Figured out a better way to see when the ramp occurred. It definitely started in May. For reference, scrobble/start is 97% of Jellyfin's api hits.

oddstr13 · 2022-10-17T19:56:28Z

Looks like events might be pushed at most every 10s?

jellyfin-plugin-trakt/Trakt/Helpers/LibraryManagerEventsHelper.cs

Lines 52 to 56 in 70a3c3a

    
           _queueTimer = new Timer( 
        
               OnQueueTimerCallback, 
        
               null, 
        
               TimeSpan.FromMilliseconds(10000), 
        
               Timeout.InfiniteTimeSpan);

But that probably also means it's updating playback position every 10s.
I haven't really dug into this plugin before, so I'm not familiar with how the internals work.

Gylesie · 2022-10-17T20:12:49Z

I am not a Jellyfin team member nor on a trakt plugin team. Just trying to add my 2 cents here to try to help resolve this issue. Here it seems that this plugin is calling /scrobble/start endpoint with a currnet progress % every time the media progresses in playback (in my case every 6 seconds):

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Lines 363 to 368 in 70a3c3a

    
           _logger.LogDebug("Sending movie playback status update to trakt.tv for user {User}.", user.Username); 
        
           await _traktApi.SendMovieStatusUpdateAsync( 
        
               movie, 
        
               MediaStatus.Watching, 
        
               traktUser, 
        
               progressPercent).ConfigureAwait(false);

After reviewing my old logs I can see all the requests and the log messages.

oddstr13 · 2022-10-17T20:20:03Z

This looks like an interesting log call to watch for when debugging, along with whatever follows

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Line 317 in 70a3c3a

    
           _logger.LogDebug("User {User} progressed watching item {Item}.", user.Username, playbackProgressEventArgs.Item.Path);

oddstr13 · 2022-10-17T20:34:28Z

My server which is still running Jellyfin 10.7.7 with Trakt plugin v12 seems to be behaving just fine (which makes sense, as this was released long before the issue started happening)

Log from 10.7.7

[2022-10-15 17:35:16.089 +00:00] [INF] [62] Trakt.ServerMediator: Playback Started
[2022-10-15 17:35:16.089 +00:00] [DBG] [62] Trakt.ServerMediator: deadbeef appears to be monitoring /mnt/Media/Foo S01E03.mkv
[2022-10-15 17:35:16.089 +00:00] [DBG] [62] Trakt.ServerMediator: Send episode status update
[2022-10-15 18:15:46.861 +00:00] [INF] [59] Trakt.ServerMediator: Playback Stopped
[2022-10-15 18:15:46.866 +00:00] [INF] [59] Trakt.ServerMediator: Item is played. Scrobble
[2022-10-15 18:16:10.419 +00:00] [INF] [20] Trakt.ServerMediator: Playback Started
[2022-10-15 18:16:10.419 +00:00] [DBG] [20] Trakt.ServerMediator: deadbeef appears to be monitoring /mnt/Media/Bar S01E03.mkv
[2022-10-15 18:16:10.419 +00:00] [DBG] [20] Trakt.ServerMediator: Send episode status update
[2022-10-15 18:40:28.800 +00:00] [INF] [71] Trakt.ServerMediator: Playback Stopped
[2022-10-15 18:40:28.800 +00:00] [INF] [71] Trakt.ServerMediator: Item is played. Scrobble
[2022-10-15 18:41:15.953 +00:00] [INF] [51] Trakt.ServerMediator: Playback Started
[2022-10-15 18:41:15.954 +00:00] [DBG] [51] Trakt.ServerMediator: deadbeef appears to be monitoring /mnt/Media/S03E02.mkv
[2022-10-15 18:41:15.954 +00:00] [DBG] [51] Trakt.ServerMediator: Send episode status update
[2022-10-15 19:04:59.201 +00:00] [INF] [59] Trakt.ServerMediator: Playback Stopped
[2022-10-15 19:04:59.206 +00:00] [INF] [59] Trakt.ServerMediator: Item is played. Scrobble
[2022-10-15 19:05:18.657 +00:00] [INF] [29] Trakt.ServerMediator: Playback Started
[2022-10-15 19:05:18.657 +00:00] [DBG] [29] Trakt.ServerMediator: deadbeef appears to be monitoring /mnt/Media/S03E03.mkv
[2022-10-15 19:05:18.657 +00:00] [DBG] [29] Trakt.ServerMediator: Send episode status update
[2022-10-15 19:29:01.260 +00:00] [INF] [34] Trakt.ServerMediator: Playback Stopped
[2022-10-15 19:29:01.260 +00:00] [INF] [34] Trakt.ServerMediator: Item is played. Scrobble
[2022-10-15 19:29:32.636 +00:00] [INF] [6] Trakt.ServerMediator: Playback Started
[2022-10-15 19:29:32.636 +00:00] [DBG] [6] Trakt.ServerMediator: deadbeef appears to be monitoring /mnt/Media/S03E04.mkv
[2022-10-15 19:29:32.636 +00:00] [DBG] [6] Trakt.ServerMediator: Send episode status update
[2022-10-15 19:55:12.112 +00:00] [INF] [87] Trakt.ServerMediator: Playback Stopped
[2022-10-15 19:55:12.113 +00:00] [INF] [87] Trakt.ServerMediator: Item is played. Scrobble

Shadowghost · 2022-10-17T21:08:00Z

Seems like I'm late to the party. I rewrote the syncing to actually do what it was intended to do.
Let me outline what is curtently happening:

The plugin subscribes to Jellyfin playback events, namely the PlaybackStart, PlaybackProgress and PlaybackStopped events from the SessionManager
PlaybackStart and PlaybackStop are quite self explanatory and are only sent once on each event
Jellyfin continually triggers PlaybackProgress events when media is played, sadly this also is the case if the media is paused. So while the player is active and in paused state Jellyfin keeps sending PlaybackProgress events

I guess the latter point is where things are going wrong:

curently we are keeping an internal playback state with the playback position of the last PlaybackProgress event to be able to notice pauses, resumes and skips
Based on the event state we receive from Jellyfin an the state we keep in our local database we only send pause/resume events once:

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Line 321 in 1ed81ff

if (playbackProgressEventArgs.IsPaused)

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Line 357 in 1ed81ff

if (state.IsPaused)
If we are progressing and not paused we compare the runtime ticks of the current state with the one we saved before. If the difference is more than 5 seconds we scrobble to trakt:

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Line 383 in 1ed81ff

else if (Math.Abs((playbackProgressEventArgs.PlaybackPositionTicks ?? 0L) - state.PlaybackProgress) > TimeSpan.TicksPerSecond * 5)

We are also sending a pause event instead of a stop event if a user interrupts playback before finishing the media:

jellyfin-plugin-trakt/Trakt/ServerMediator.cs

Line 495 in 1ed81ff

    
           _logger.LogDebug("User {User} didn't watch item {Item} until the end. Not scrobbling but pausing playback at current playback position.", user.Username, playbackStoppedEventArgs.Item.Name);

The 10 second timer mentioned earlier is for library events (addition/removal of media) and not for playback tracking.
Library events are also chunked together into batches of 100 items:

jellyfin-plugin-trakt/Trakt/Api/TraktApi.cs

Line 292 in 70a3c3a

var responses = new List<TraktSyncResponse>();

My guess is that something in the skip calculation (the 5 seconds mentioned earlier) is going wrong but I was quite sure I did test this to not happen - exactly because I didn't want to hammer the API...

I will look into this more over the week but it may take some time.

oddstr13 · 2022-10-17T21:11:11Z

@Gylesie are you seeing Trakt.ServerMediator: Playback skipped along with the sending movie playback status update message every 6s?

rudf0rd · 2022-10-17T21:13:54Z

@Shadowghost Just to make sure I'm understanding, the scrobble event is intentionally sent every 5s? If so, that can be removed and this would be fixed I think. We only require one start event to be sent.

Apologies if I misunderstood!

anthonylavado · 2022-10-17T21:19:55Z

@rudford Since I handle all our API keys and 3rd party accounts, I figure I should ask this: I don't see a way to generate a new ID/Secret from the Applications page. Is there a way we can arrange this?
Though automatic plugin updates are enabled by default, we can't be sure everyone updates. If we just enable the existing one, you'll likely still be flooded.

oddstr13 · 2022-10-17T21:20:01Z

@Shadowghost Just to make sure I'm understanding, the scrobble event is intentionally sent every 5s? If so, that can be removed and this would be fixed I think. We only require one start event to be sent.

Apologies if I misunderstood!

As I understand it, the intent is to send an explicit update if the playback position jumps more than 5s (user skipped a section, the intro/credits or some such).

It's possible the logic around this isn't 100% sane, but it could also be possible that the server isn't getting the position updates from the client often enough not to trigger the skip detection (I haven't completely wrapped my head around this code yet)

Shadowghost · 2022-10-17T21:26:19Z

@Shadowghost Just to make sure I'm understanding, the scrobble event is intentionally sent every 5s? If so, that can be removed and this would be fixed I think. We only require one start event to be sent.

Apologies if I misunderstood!

It should only be sent if the difference between the saved and the event runtimeticks is more than 5 seconds.
This was a workaround I came up with to be able to handle skipping without sending all playback progress events to your API because I wanted to prevent hammering your API...

From taking a quick look on how those events are fired from the Jellyfin side it seems like it depends on how frequent the clients send the update event. So increasing the buffer to like 10 or 15 seconds might solve it.

rudf0rd · 2022-10-17T21:31:44Z

@Shadowghost I see! So this is strictly to be accurate on the progress indicator on Trakt. If it makes sense to you, maybe 60s would be better? I don't know the architecture like you do, but it seems to me that the need for that kind of accuracy doesn't match the impact it can have on the API. Of course I'm being overprotective of the API resources :D

@anthonylavado I was thinking the same. If it's cool with you, I can regenerate the API key and you can grab it off your app settings.

anthonylavado · 2022-10-17T21:33:07Z

@rudf0rd re:API Key - Sounds good.

Re: updating progress - we're currently exploring how this is working across all our different clients. We'll sort something out soon.

rudf0rd · 2022-10-17T21:42:24Z

@anthonylavado updated

Gylesie · 2022-10-17T21:46:24Z

@Gylesie are you seeing Trakt.ServerMediator: Playback skipped along with the sending movie playback status update message every 6s?

Yes, exactly, even though the playback was continuous. As @Shadowghost pointed out, maybe the client is too slow with the update events. In this particular case it was the Jellyfin Media Player client.

Logs:

[DBG] [32] Trakt.ServerMediator: Playback progressed
[DBG] [32] Trakt.ServerMediator: User "xxxxx" progressed watching item "xxxxxxxxxxxxxxxxxxxxxxxxxx".
[DBG] [32] Trakt.ServerMediator: Playback skipped
[DBG] [32] Trakt.ServerMediator: Sending episode playback status update to trakt.tv for user "xxxxx".
[DBG] [32] Trakt.Api.TraktApi: TraktScrobbleEpisode { xxxxxxxxx }

There were no skips.

Shadowghost · 2022-10-17T22:17:56Z

Progress intervals of some of our apps (sourced from our Matrix chat):

Jellyfin-web: 1 second on playback, 10 seconds while paused
Android: 10 seconds
Android TV: 3 seconds while playing, 15 seconds while paused
Jellycon: 10 seconds
Jellyfin4Kodi: 11 seconds
Roku: 30 seconds
Mopidy: 1 Minute

#175 will compare the timestamp difference of the events to the difference between runtime ticks to check for skips (min. 15 seconds).
I tested it with Jellyfin-web and it seems to work as intended. Additional test would be appreciated.

anthonylavado · 2022-10-18T16:01:50Z

@rudf0rd I see we got a new Client ID, but not a new Client Secret. Was that intentional? Our auth tests are currently failing.

rudf0rd · 2022-10-18T17:24:33Z

Apologies. Forgot to approve the app. Should be good now.

zaourzag · 2022-10-31T06:19:27Z

I ended up creating a fork to mitigate the rate limit issues. You can find it here this will be updates from time to time.the only difference is that it has my own creds

TastyPi · 2022-10-31T09:04:38Z

Would it be worth allowing people to provide their own API keys to avoid this in the future?

foux · 2022-10-31T09:07:48Z

I don't think it's a good idea. If another issue appears with the code, there will be a lot of keys out there, and Trakt won't be able to invalidate them all easily.

daullmer · 2022-10-31T09:11:30Z

None of the proposed solutions would fix the underlying problem. The fork @zaourzag created only changes the keys. While this would allow the forked plugin to work if Trakt disabled the Jellyfin key again, it wouldn't fix the problem that the plugin is hammering the Trakt API.

foux · 2022-10-31T09:12:56Z

What hammering are you talking about? This issue was fixed 11 days ago on version 21.

daullmer · 2022-10-31T09:15:09Z

It is fixed now. But if there would still be a problem, the fork or allowing people to provide their own keys would do absolutely nothing.

This comment was marked as off-topic.

Sign in to view

Shadowghost mentioned this issue Oct 17, 2022

Do not hammer the API #175

Merged

This was referenced Oct 18, 2022

An error occurred when trying to authorize device: 500 - Internal Server Error #176

Closed

Can't authorize device #177

Closed

This was referenced Oct 19, 2022

Exception - Response status code does not indicate success 403 Forbidden #178

Closed

Trakt plugin seems to be not working #179

Closed

crobibero changed the title ~~Issue with spamming Trakt API~~ [Plugin Disabled] Issue with spamming Trakt API Oct 19, 2022

crobibero pinned this issue Oct 19, 2022

crobibero closed this as completed in #175 Oct 20, 2022

zotabee mentioned this issue Nov 26, 2023

Trakt.Api.TraktApi: Too many requests while communicating with trakt.tv #208

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Plugin Disabled] Issue with spamming Trakt API #174

[Plugin Disabled] Issue with spamming Trakt API #174

rudf0rd commented Oct 17, 2022 •

edited by crobibero

SenorSmartyPants commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

SenorSmartyPants commented Oct 17, 2022

rudf0rd commented Oct 17, 2022 •

edited

oddstr13 commented Oct 17, 2022

Gylesie commented Oct 17, 2022

This comment was marked as off-topic.

oddstr13 commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

Shadowghost commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

Shadowghost commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

Gylesie commented Oct 17, 2022

Shadowghost commented Oct 17, 2022 •

edited

anthonylavado commented Oct 18, 2022

rudf0rd commented Oct 18, 2022 via email •

edited

zaourzag commented Oct 31, 2022 •

edited

TastyPi commented Oct 31, 2022

foux commented Oct 31, 2022 •

edited

daullmer commented Oct 31, 2022

foux commented Oct 31, 2022

daullmer commented Oct 31, 2022

[Plugin Disabled] Issue with spamming Trakt API #174

[Plugin Disabled] Issue with spamming Trakt API #174

Comments

rudf0rd commented Oct 17, 2022 • edited by crobibero

Original message:

SenorSmartyPants commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

SenorSmartyPants commented Oct 17, 2022

rudf0rd commented Oct 17, 2022 • edited

oddstr13 commented Oct 17, 2022

Gylesie commented Oct 17, 2022

This comment was marked as off-topic.

oddstr13 commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

Shadowghost commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

oddstr13 commented Oct 17, 2022

Shadowghost commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

anthonylavado commented Oct 17, 2022

rudf0rd commented Oct 17, 2022

Gylesie commented Oct 17, 2022

Shadowghost commented Oct 17, 2022 • edited

anthonylavado commented Oct 18, 2022

rudf0rd commented Oct 18, 2022 via email • edited

zaourzag commented Oct 31, 2022 • edited

TastyPi commented Oct 31, 2022

foux commented Oct 31, 2022 • edited

daullmer commented Oct 31, 2022

foux commented Oct 31, 2022

daullmer commented Oct 31, 2022

rudf0rd commented Oct 17, 2022 •

edited by crobibero

rudf0rd commented Oct 17, 2022 •

edited

Shadowghost commented Oct 17, 2022 •

edited

rudf0rd commented Oct 18, 2022 via email •

edited

zaourzag commented Oct 31, 2022 •

edited

foux commented Oct 31, 2022 •

edited