Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update since 0.28.2

Taxel / PlexTraktSync

A python script that syncs the movies, shows and ratings between trakt and Plex (without needing a PlexPass or Trakt VIP subscription)

MIT License

1.6k stars 105 forks source link

Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update since 0.28.2 #1724

Closed zeroquinc closed 9 months ago

zeroquinc commented 9 months ago

Confirmation

[X] I have read the README.md on the project homepage
[X] I have checked if identical issue already exists
[X] I have tried downgrading to find version that can be used as a workaround

The problem

I keep getting a Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update every 1 second when I run PlexTraktSync with the watch command since version v0.28.x

Error trace / logs

INFO     Listening for events!
INFO     Server connected: skywalker (1.32.8.7639-fb6452ebf)
INFO     Starting AlertListener:
INFO     Websocket connected
ERROR    KeyError was raised: 'sessionKey'
ERROR    KeyError was raised: 'sessionKey'
INFO     on_play: <Movie:1195:Napoleon>: 0.067816%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.080719%, State: playing, Watched:
         False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 0.091628%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.102349%, State: playing, Watched:
         False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 0.113143%, State: playing, Watched:
         False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)

Expected behavior

To scrobble without hitting the Rate Limit.

Steps to reproduce the behavior

removed all plextraktsync dockers and configs
deployed plextraktsync and login
sync works fine, but almost immediately notice Rate Limit Exceeded in the logs.

Inspect of problematic items

Seems to be happening since this commit: https://github.com/Taxel/PlexTraktSync/commit/48ace04932e4fae10be29b1527bd2803f390f1a5

Workarounds

Reverting back to v0.27.15 got rid of the Rate Limit Exceeded errors. I didn't try other versions.

INFO     Listening for events!
INFO     Starting AlertListener:
INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 0.016007%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.026770%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.037711%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.048589%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.059288%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.070197%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.081149%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.091995%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.102800%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.113740%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.124681%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.135496%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.146437%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.157242%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.169053%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.179836%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.190714%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.201498%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.212197%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.223012%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.233880%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.246877%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.255667%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.266587%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.279437%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.290189%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.301130%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.312102%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.322980%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.333795%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.344673%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.355540%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.366334%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.377201%, State: playing, Watched:
         False, LastViewed: None
INFO     on_play: <Movie:1195:Napoleon>: 0.388111%, State: playing, Watched:
         False, LastViewed: None

Install method

docker-compose

Config file contents

# Config File: /app/config/config.yml
cache:
  path: /app/config/trakt_cache
excluded-libraries:
- Private
- Family Holidays
config:
  dotenv_override: true
plex:
  timeout: 30
logging:
  append: true
  console_time: false
  debug: false
  filename: plextraktsync.log
  filter_loggers: null
  filter: null
sync:
  plex_to_trakt:
    collection: true
    clear_collected: false
    ratings: false
    watched_status: false
    watchlist: false
  trakt_to_plex:
    liked_lists: false
    ratings: false
    watched_status: false
    watchlist: false
    watchlist_as_playlist: false
  rating_priority: plex
watch:
  add_collection: false
  remove_collection: false
  scrobble_threshold: 80
  username_filter: true
  media_progressbar: true
xbmc-providers:
  movies: imdb
  shows: tvdb

Version

0.28.2

Python Version

3.12.1

Plex Server Version

1.32.8.7639

Operating System and Version

Ubuntu 22.04

glensc commented 9 months ago

Seems to be happening since this commit: https://github.com/Taxel/PlexTraktSync/commit/48ace04932e4fae10be29b1527bd2803f390f1a5

If you revert it, you no longer get the rate limit messages?

because, that commit is supposed to help in cases rate limit happens, i.e retry the query, so previous version should just print error similarly, but not retry.

glensc commented 9 months ago

48ace049 was added in 0.28.1, so 0.28.0 is fine?

and please, exact versions not 0.28.x

zeroquinc commented 9 months ago

48ace04 was added in 0.28.1, so 0.28.0 is fine?

and please, exact versions not 0.28.x

I just tested 0.27.16, 0.28.0, 0.28.1 and 0.28.2. It seems to started on 0.28.0.

0.27.16:

INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 12.117320%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.130265%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.141059%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.151853%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.162815%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.173745%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.184539%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.195406%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.204176%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.214928%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39
INFO     on_play: <Movie:1195:Napoleon>: 12.225743%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:19:39

0.28.0 starts throwing Rate Limted Exceeded:

INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 11.109496%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.122167%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
ERROR    RateLimitException was raised: Rate Limit Exceeded
INFO     on_play: <Movie:1195:Napoleon>: 11.132877%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.143514%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.154235%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.164787%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.175466%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.186050%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.196582%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.207176%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13
INFO     on_play: <Movie:1195:Napoleon>: 11.217729%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:13:13

And on 0.28.2 it started adding plextraktsync.trakt.ScrobberProxy.update:

INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 11.920060%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
INFO     on_play: <Movie:1195:Napoleon>: 11.932910%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 11.943715%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
INFO     on_play: <Movie:1195:Napoleon>: 11.954456%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 11.965083%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
INFO     on_play: <Movie:1195:Napoleon>: 11.975730%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 11.986387%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
INFO     on_play: <Movie:1195:Napoleon>: 11.997024%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53

glensc commented 9 months ago

so it started getting rate limit errors from 0.28.0 (not 0.28.2), and as said before, 0.28.1 only adds retry to the rate limits. I started getting them too myself, so I guessed it was because I was running watch command 3 times and added retry to the methods.

as for 0.28.0, there's api domain change:

https://github.com/Taxel/PlexTraktSync/pull/1710
- https://github.com/glensc/python-pytrakt/pull/34

could be that the official domain has higher rate limits. can you hack the code and change back to old domain:

https://github.com/glensc/python-pytrakt/pull/34/files

you could also enable debug logging and see the request rate to trakt.tv/scrobble:

2024-01-11 23:16:59,704 DEBUG[trakt.core]:post: https://api.trakt.tv/scrobble/start
2024-01-11 23:17:15,448 DEBUG[trakt.core]:post: https://api.trakt.tv/scrobble/stop

glensc commented 9 months ago

@zeroquinc can you test with old domain then?

zeroquinc commented 9 months ago

@zeroquinc can you test with old domain then?

Sorry, I didn't had time but I have now.

could be that the official domain has higher rate limits. can you hack the code and change back to old domain:

I tried, but I have no clue how to do this. I would love to test this for you though to have it fixed.

glensc commented 9 months ago

I tried, but I have no clue how to do this. I would love to test this for you though to have it fixed.

See the pull request I was referring to: https://github.com/glensc/python-pytrakt/pull/34/files

do you see the filename and the change?

edit that file and then start the watch command

zeroquinc commented 9 months ago

I tried, but I have no clue how to do this. I would love to test this for you though to have it fixed.

See the pull request I was referring to: https://github.com/glensc/python-pytrakt/pull/34/files

do you see the filename and the change?

edit that file and then start the watch command

I saw the pull request you referred to yes, but I use this in docker and my /opt/plextraktsync don't have any of these files because this seems to be the python-pytrakt module. How can I edit this file?

glensc commented 9 months ago

$ docker-compose run --user=root -e PUID= -e PGID= --rm plextraktsync sh
# vi /usr/local/lib/python3.12/site-packages/trakt/core.py

or you could create copy of that file and mount bind mount to that path

    volumes:
      - ./core.py:/usr/local/lib/python3.12/site-packages/trakt/core.py

zeroquinc commented 9 months ago

$ docker-compose run --user=root -e PUID= -e PGID= --rm plextraktsync sh
# vi /usr/local/lib/python3.12/site-packages/trakt/core.py

or you could create copy of that file and mount bind mount to that path

    volumes:
      - ./core.py:/usr/local/lib/python3.12/site-packages/trakt/core.py

Thanks, I changed the API endpoint to https://api-v2launch.trakt.tv/ and I don't get any Rate Limits now on the latest tag:

INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 12.859786%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.870506%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.881258%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.891989%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.904724%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.915350%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.926039%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12
INFO     on_play: <Movie:1195:Napoleon>: 12.936938%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:24:12

It also stopped on 0.28.2 (just in case because this was the version I originally had problems with)

INFO     Websocket connected
INFO     on_play: <Movie:1195:Napoleon>: 13.755171%, State: paused, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.755171%, State: paused, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.755171%, State: paused, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.755171%, State: paused, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.759388%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.770223%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.781038%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.791832%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:25:37
INFO     on_play: <Movie:1195:Napoleon>: 13.802773%, State: playing, Watched:
         False, LastViewed: 2024-01-13 16:25:37

glensc commented 9 months ago

ok. so maybe then it was trakt api site wide problem that is resolved now?

zeroquinc commented 9 months ago

ok. so maybe then it was trakt api site wide problem that is resolved now?

Nope, still immediately get Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update on latest again after switching back to the new API url. ~~Guess I'll stay on 0.27.16 for a while.~~ Well I just read that the URL will get deprecated on the 1st of February. Hope we can fix it because my scrobbles are out of sync now because of the Rate Limit Exceeded.

glensc commented 9 months ago

Hope we can fix it because my scrobbles are out of sync now because of the Rate Limit Exceeded.

nope. it retries 1 time and then it's fine. program will exit if it can't retry.

glensc commented 9 months ago

trakt replied that same rate limits:

https://x.com/traktapi/status/1747308407533818321?s=20

So, I'm wondering why it appears like domain change gets into rate limit trouble?

glensc commented 9 months ago

Hope we can fix it because my scrobbles are out of sync now because of the Rate Limit Exceeded.

nope. it retries 1 time and then it's fine. program will exit if it can't retry.

@zeroquinc you didn't respond to this. correct? Am I missing something?

from your logs I see it retried and that helped

INFO     on_play: <Movie:1195:Napoleon>: 11.975730%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 11.986387%, State: playing, Watched:

zeroquinc commented 9 months ago

Hope we can fix it because my scrobbles are out of sync now because of the Rate Limit Exceeded.

nope. it retries 1 time and then it's fine. program will exit if it can't retry.

@zeroquinc you didn't respond to this. correct? Am I missing something?

from your logs I see it retried and that helped
INFO     on_play: <Movie:1195:Napoleon>: 11.975730%, State: playing, Watched:
         False, LastViewed: 2024-01-11 21:15:53
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Movie:1195:Napoleon>: 11.986387%, State: playing, Watched:

Please keep the issue open until this weekend. I'll update to the latest version today and I'll test it for 2 days to see if it doesn't miss any scrobbles. If it doesn't, we can close it I guess. Although it would be nice to be able to at least filter all the errors out.

I'll update this within 48 hours.

zeroquinc commented 9 months ago

Yeah, I do get out of syncs with the latest version. Just stopped the episode and Trakt still shows its scrobbling at 85%. Have absolutely zero issues on 0.27.16 with also the correct percentage while its scrobbling and if I pause it it shows it instantly on Trakt. Now it's still showing as scrobbling 3 minutes after I stopped the episode.

Very weird, just checked the logs and it still shows as scrobbling while I stopped the episode 5 minutes ago.

         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 95.620810%, State:
         playing, Watched: False, LastViewed: None
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 95.662229%, State:
         playing, Watched: False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 95.695243%, State:
         playing, Watched: False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 95.736542%, State:
         playing, Watched: False, LastViewed: None
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 95.778162%, State:
         playing, Watched: False, LastViewed: None
WARNING  Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update(),
         retrying after 1 seconds (try: 1/2)

EDIT: Finally it stopped, it seems like its literally around 7 minutes behind.

         retrying after 1 seconds (try: 1/2)
ERROR    KeyError was raised: 'sessionKey'
INFO     on_play: <Episode:1287:Prison-Break-s02e01>: 98.830658%, State:
         stopped, Watched: False, LastViewed: None
ERROR    KeyError was raised: 'sessionKey'

It marks it as played, but with a 5 to 8 minutes delay. This doesn't happen on 0.27.16. All instantly.

EDIT2: ~~Well, I played 4 episodes in a row now and they all scrobbled fine without any delay.~~ Nevermind, I looked wrong. It's still like 5 minutes behind.

As you can see here, the next episode is already playing for 1 minute but Plextraktsync is still scrobbling the episode from before: It also completely missed the E04 scrobble now. It didnt marked it as watched on Trakt.

glensc commented 9 months ago

you can perhaps enable debug log and check the rate of scribble api requests made. are they more frequent then?

glensc commented 9 months ago

and are you sure you not running another instance of the script from same outgoing ip?

glensc commented 9 months ago

and you should make another issue with ERROR KeyError was raised: 'sessionKey' error. I'm guessing debug log contains trace as well where it comes from.

zeroquinc commented 9 months ago

and are you sure you not running another instance of the script from same outgoing ip?

I think I know what is going on. Last week my provider turned on CGNAT. Which basicly means because they are running out of IPv4 addresses they give you a 100.xx.xx.xx IP which you share with other people. Since I found out about that yesterday, because I couldnt connect to my VPN anymore, I called their servicedesk and they turned it off for me and my IP switched back to a similar one I had before. I rebooted my server and container and I don't get the warnings anymore. I think it worked fine on the old version because that API wasn't used a lot anymore. Sorry for the inconvenience. I hope this is it because I haven't seen the error since.

I'll make an issue about the sessionKey error when I get it again, I turned on debugging for now.

glensc commented 9 months ago

if I look my plextraktsync log, I see it submits results every 10s, not often

$ grep trakt.tv/scrobble/start plextraktsync.log | grep RESPONSE
2024-01-20 20:33:21,229 DEBUG[trakt.core]:RESPONSE [post] (https://api.trakt.tv/scrobble/start): <Response [201]>
2024-01-20 20:33:31,125 DEBUG[trakt.core]:RESPONSE [post] (https://api.trakt.tv/scrobble/start): <Response [201]>
2024-01-20 20:33:41,222 DEBUG[trakt.core]:RESPONSE [post] (https://api.trakt.tv/scrobble/start): <Response [201]>
2024-01-20 20:33:51,142 DEBUG[trakt.core]:RESPONSE [post] (https://api.trakt.tv/scrobble/start): <Response [201]>

glensc commented 9 months ago

you may also test this pr:

https://github.com/Taxel/PlexTraktSync/pull/1757

it will limit requests made by this application not to exceed thresholds.

zeroquinc commented 9 months ago

I get them again ofcourse 10 minutes after I posted that I didn't see the errors anymore..

2024-01-20 19:53:57,212 DEBUG[PlexTraktSync.ScrobblerProxy]:pause(<TVEpisode>: Prison Break S2E7 Buried): 81.06772727272727
2024-01-20 19:53:57,213 DEBUG[trakt.core]:post: https://api.trakt.tv/scrobble/pause
2024-01-20 19:53:57,213 DEBUG[trakt.core]:method, url :: post, https://api.trakt.tv/scrobble/pause
2024-01-20 19:53:57,216 DEBUG[requests_cache.policy.actions]:Cache directives from request headers: CacheDirectives()
2024-01-20 19:53:57,217 DEBUG[requests_cache.policy.actions]:Pre-read cache checks: disabled method
2024-01-20 19:53:57,217 DEBUG[requests_cache.policy.actions]:Post-read cache actions: CacheActions(expire_after=-1, send_request=True, skip_read=True)
2024-01-20 19:53:57,324 DEBUG[urllib3.connectionpool]:https://api.trakt.tv:443 "POST /scrobble/pause HTTP/1.1" 429 None
2024-01-20 19:53:57,326 DEBUG[requests_cache.policy.actions]:Cache directives from response headers: CacheDirectives(no_cache=True)
2024-01-20 19:53:57,326 DEBUG[requests_cache.policy.actions]:Pre-write cache checks: disabled method, disabled status
2024-01-20 19:53:57,326 DEBUG[requests_cache.session]:Skipping cache write for URL: https://api.trakt.tv/scrobble/pause
2024-01-20 19:53:57,326 DEBUG[trakt.core]:RESPONSE [post] (https://api.trakt.tv/scrobble/pause): <Response [429]>
2024-01-20 19:53:57,326 WARNING[PlexTraktSync]:Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.pause(), retrying after 1 seconds (try: 1/2)
2024-01-20 19:53:57,330 DEBUG[PlexTraktSync]:{'name': 'AUTHED_API_POST_LIMIT', 'period': 1, 'limit': 1, 'remaining': 0, 'until': '2024-01-20T18:53:58Z'}
2024-01-20 19:53:58,331 DEBUG[PlexTraktSync.ScrobblerProxy]:pause(<TVEpisode>: Prison Break S2E7 Buried): 81.06772727272727

you may also test this pr:
* [Refactor: Add TraktScrobbleWorker worker #1757](https://github.com/Taxel/PlexTraktSync/pull/1757)
it will limit requests made by this application not to exceed thresholds.

I will test it, can you give a brief description on how to merge this in my docker image?

glensc commented 9 months ago

see readme.md how to install from pull request.

glensc commented 9 months ago

the idea of logs checking was to check how often it plextraktsync makes the scribble post requests. i.e. the log entry timestamps.

zeroquinc commented 9 months ago

see readme.md how to install from pull request.

Doesn't seem to work. Followed instructions but got an error, I installed it via pipx for convenience. Instructions we're pretty clear.

desiler@skywalker:~$ plextraktsync@1757 self-update
Installed as pr #1757, enabling pr mode
Uninstalling previous plextraktsync@1757
pipx uninstall plextraktsync@1757
uninstalled PlexTraktSync@1757! ✨ 🌟 ✨
Updating PlexTraktSync to the pull request #1757 version using pipx
pipx install --suffix=@1757 --force git+https://github.com/Taxel/PlexTraktSync@refs/pull/1757/head
  installed package PlexTraktSync 0.28.0.dev0 (PlexTraktSync@1757), installed using Python 3.10.12
  These apps are now globally available
    - plextraktsync@1757
done! ✨ 🌟 ✨
desiler@skywalker:~$ plextraktsync@1757 watch
INFO     Connecting with url: https://xxx.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct:32400, timeout 30 seconds
ERROR    HTTPSConnectionPool(host='xxx.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct', port=32400): Max retries exceeded with url: / (Caused by
         NameResolutionError("<urllib3.connection.HTTPSConnection object at 0x7f94ecc556c0>: Failed to resolve '192-168-0-150.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct'
         ([Errno -3] Temporary failure in name resolution)"))
WARNING  Adding rewritten http url to connect with: http://xxx.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct:32400
INFO     Connecting with url: https://172-18-0-1.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct:32400, timeout 30 seconds
ERROR    HTTPSConnectionPool(host='172-18-0-1.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct', port=32400): Max retries exceeded with url: / (Caused by
         NameResolutionError("<urllib3.connection.HTTPSConnection object at 0x7f94ecc563b0>: Failed to resolve '172-18-0-1.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct' ([Errno
         -3] Temporary failure in name resolution)"))
WARNING  Adding rewritten http url to connect with: http://172-18-0-1.3e3569cb1a934e20a2b3b210ea983d2b.plex.direct:32400
INFO     Connecting with url: http://xxx, timeout 30 seconds
ERROR    No module named 'plextraktsync.media'
         ╭───────────────────────────────────────────────────────────────── Traceback (most recent call last) ──────────────────────────────────────────────────────────────────╮         │ /home/desiler/.local/pipx/venvs/plextraktsync@1757/lib/python3.10/site-packages/plextraktsync/cli.py:26 in wrap                                                      │         │                                                                                                                                                                      │         │    23 │   │   │   cmd = getattr(module, name)                                                                                                                        │         │    24 │   │   │                                                                                                                                                      │         │    25 │   │   │   try:                                                                                                                                               │         │ ❱  26 │   │   │   │   cmd(*args, **kwargs)                                                                                                                           │         │    27 │   │   │   except ClickException as e:                                                                                                                        │         │    28 │   │   │   │   from plextraktsync.factory import logger                                                                                                       │         │    29 │   │   │   │   logger.fatal(f"Error running {name} command: {str(e)}")                                                                                        │         │                                                                                                                                                                      │         │ /home/desiler/.local/pipx/venvs/plextraktsync@1757/lib/python3.10/site-packages/plextraktsync/commands/watch.py:14 in watch                                          │         │                                                                                                                                                                      │         │   11 │   │   server=server,                                                                                                                                          │         │   12 │   )                                                                                                                                                           │         │   13 │   ws = factory.web_socket_listener                                                                                                                            │         │ ❱ 14 │   updater = factory.watch_state_updater                                                                                                                       │         │   15 │                                                                                                                                                               │         │   16 │   ws.on(ServerStarted, updater.on_start)                                                                                                                      │         │   17 │   ws.on(                                                                                                                                                      │         │                                                                                                                                                                      │         │ /usr/lib/python3.10/functools.py:981 in __get__                                                                                                                      │         │                                                                                                                                                                      │         │   978 │   │   │   │   # check if another thread filled cache while we awaited lock                                                                                   │         │   979 │   │   │   │   val = cache.get(self.attrname, _NOT_FOUND)                                                                                                     │         │   980 │   │   │   │   if val is _NOT_FOUND:                                                                                                                          │         │ ❱ 981 │   │   │   │   │   val = self.func(instance)                                                                                                                  │         │   982 │   │   │   │   │   try:                                                                                                                                       │         │   983 │   │   │   │   │   │   cache[self.attrname] = val                                                                                                             │         │   984 │   │   │   │   │   except TypeError:                                                                                                                          │         │                                                                                                                                                                      │         │ /home/desiler/.local/pipx/venvs/plextraktsync@1757/lib/python3.10/site-packages/plextraktsync/util/Factory.py:213 in watch_state_updater                             │         │                                                                                                                                                                      │         │   210 │   │   return WatchStateUpdater(                                                                                                                              │         │   211 │   │   │   plex=self.plex_api,                                                                                                                                │         │   212 │   │   │   trakt=self.trakt_api,                                                                                                                              │         │ ❱ 213 │   │   │   mf=self.media_factory,                                                                                                                             │         │   214 │   │   │   config=self.config,                                                                                                                                │         │   215 │   │   )                                                                                                                                                      │         │   216                                                                                                                                                                │         │                                                                                                                                                                      │         │ /usr/lib/python3.10/functools.py:981 in __get__                                                                                                                      │         │                                                                                                                                                                      │         │   978 │   │   │   │   # check if another thread filled cache while we awaited lock                                                                                   │         │   979 │   │   │   │   val = cache.get(self.attrname, _NOT_FOUND)                                                                                                     │         │   980 │   │   │   │   if val is _NOT_FOUND:                                                                                                                          │         │ ❱ 981 │   │   │   │   │   val = self.func(instance)                                                                                                                  │         │   982 │   │   │   │   │   try:                                                                                                                                       │         │   983 │   │   │   │   │   │   cache[self.attrname] = val                                                                                                             │         │   984 │   │   │   │   │   except TypeError:                                                                                                                          │         │                                                                                                                                                                      │         │ /home/desiler/.local/pipx/venvs/plextraktsync@1757/lib/python3.10/site-packages/plextraktsync/util/Factory.py:54 in media_factory                                    │         │                                                                                                                                                                      │         │    51 │                                                                                                                                                              │         │    52 │   @cached_property                                                                                                                                           │         │    53 │   def media_factory(self):                                                                                                                                   │         │ ❱  54 │   │   from plextraktsync.media.MediaFactory import MediaFactory                                                                                              │         │    55 │   │                                                                                                                                                          │         │    56 │   │   trakt = self.trakt_api                                                                                                                                 │         │    57 │   │   plex = self.plex_api                                                                                                                                   │         ╰──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────╯         ModuleNotFoundError: No module named 'plextraktsync.media'
Error: Error running watch command: No module named 'plextraktsync.media'

I also seem to get the WARNING Rate Limit Exceeded for plextraktsync.trakt.ScrobblerProxy.update() right after I start it.

glensc commented 9 months ago

Followed instructions but got an error

I don't have my crystal ball here. which instructions you follow (copy text), what did you do (share commands and output)?

Error: Error running watch command: No module named 'plextraktsync.media'

Rebased:

https://github.com/Taxel/PlexTraktSync/pull/1757#issuecomment-1904098688

ERROR HTTPSConnectionPool

you may want to edit your servers.yml and put working URL as first

zeroquinc commented 9 months ago

Followed instructions but got an error

I don't have my crystal ball here. which instructions you follow (copy text), what did you do (share commands and output)?

Error: Error running watch command: No module named 'plextraktsync.media'

Rebased:
* [Refactor: Add TraktScrobbleWorker worker #1757 (comment)](https://github.com/Taxel/PlexTraktSync/pull/1757#issuecomment-1904098688)
ERROR HTTPSConnectionPool

you may want to edit your servers.yml and put working URL as first

You dont really need a crystal ball to guess which instructions I followed, because you can literally see the what command I entered to update the git pull request.

Anyhow, thanks for updating the PR, I will try it again and edit my servers.yml so that only the URL that doesnt timeout is in it.

I still get the issue, also it seems to be way more out of sync now. I pause the episode and it still shows it scrobbling almost 10 minutes later on Trakt. It keeps spawning new workers with different percentages. here is the full log because it's a bit long:

https://pastebin.com/By2jQyZM

EDIT: 15 minutes later, I even stopped it. And logs still shows its paused and its still scrobbling on Trakt.

glensc commented 9 months ago

You dont really need a crystal ball to guess which instructions I followed, because you can literally see the what command I entered to update the git pull request.

there are at least three ways documented to install pr for docker. and I can see which one you succeeded, not the one(s) you failed.

also. don't put things to pastebin. too many ads, and the pastes expire. you can attach .txt extension files to github issues.

glensc commented 9 months ago

the docker pr install issues you were having, you should report as separate issue, or submit documentation pr to clarify problems
the pr, I was referrerring to, if it works for you (no additional breakage), add your approval and I can merge

after. that merge, the timer there could be updated not to submit more than N seconds. what would the value be? currently it's 1.1 seconds:

https://github.com/Taxel/PlexTraktSync/blob/e7007a9f8fc0f150eda04d98dc32b248de80633a/plextraktsync/config/__init__.py#L9