Sync: Crash directly each time (docker version)

typhoe commented 3 years ago

The problem

Try to run plextraktsync to sync Plex and Trakt results in crashes each time. I'm running the docker latest release (0.16.0 as of today), but I started to try from 0.15.6 I think, with same errors.

Error trace

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest sync
INFO: PlexTraktSync [0.16.0]
INFO: Syncing with Plex xxx and Trakt xxx
Sync Movies: True
Sync Shows: True
Plex Server version: 1.24.5.5173-8dcc73a59, updated at: 2021-11-01 03:53:15
Server has 11 libraries: [ xxx,xxx,xxx,... ]
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/app/plex_trakt_sync/__main__.py", line 16, in <module>
    cli()
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1659, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/app/plex_trakt_sync/commands/sync.py", line 123, in sync
    sync_all(walker=w, plex=plex, runner=factory.sync(), dry_run=dry_run)
  File "/app/plex_trakt_sync/commands/sync.py", line 19, in sync_all
    runner.sync(walker, dry_run=dry_run)
  File "/app/plex_trakt_sync/sync.py", line 64, in sync
    if self.config.trakt_to_plex["watchlist"] and trakt.watchlist_movies:
  File "/app/plex_trakt_sync/decorators/nocache.py", line 12, in inner
    return method(*args, **kwargs)
  File "/app/plex_trakt_sync/decorators/rate_limit.py", line 23, in wrapper
    return fn(*args, **kwargs)
  File "/app/plex_trakt_sync/trakt_api.py", line 137, in watchlist_movies
    return self.me.watchlist_movies
  File "/app/plex_trakt_sync/decorators/nocache.py", line 12, in inner
    return method(*args, **kwargs)
  File "/app/plex_trakt_sync/decorators/rate_limit.py", line 23, in wrapper
    return fn(*args, **kwargs)
  File "/app/plex_trakt_sync/trakt_api.py", line 75, in me
    return trakt.users.User('me')
  File "/usr/local/lib/python3.10/site-packages/trakt/users.py", line 222, in __init__
    self._get()
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 552, in inner
    json_data = self._handle_request('get', url)
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 532, in _handle_request
    json_data = json.loads(response.content.decode('UTF-8', 'ignore'))
  File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Running in "watch" mode throws that error in loop:
ERROR: AlertListener Msg Error: Expecting value: line 1 column 1 (char 0)

Expected behavior

Well, that it would sync Plex and Trakt.

Logins are ok (my conf seems good):

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest login
Checking Plex and Trakt logins
Success!

Unmatched works (with an error on the log):

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest unmatched
Sync Movies: True
Sync Shows: True
/app/plex_trakt_sync/walker.py:245: TqdmExperimentalWarning: rich is experimental/alpha
  pb = self._progressbar(iterable, **kwargs)
Processing xxx  92% ━━━━━━━━━━  86/93  [ 0:00:00 < 0:00:01 , 164 it/s ]INFO: xxx processed in 0.9 seconds
Processing xxx  55% ━━━━     17/31  [ 0:00:00 < 0:00:01 , 159     ]
                                                                       it/s     INFO: xxx processed in 0.3 seconds
Processing xxx  91% ━━━━━━━━━  67/74  [ 0:00:00 < 0:00:01 , 160 it/s ]INFO: xxx processed in 0.8 seconds
<...>

Version:

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest version
PlexTraktSync Version: 0.16.0
PlexTraktSync Git Version: [0.16.0]
Python Version: 3.10.0 (default, Oct 26 2021, 23:43:41) [GCC 10.2.1 20201203]
Plex API Version: 4.7.2
Trakt API Version: 3.2.2
Cache Dir: /app/config
Config Dir: /app/config
Log Dir: /app/config

Steps to reproduce the behavior

Try to run sync:

docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest sync

Inspect of problematic items

Inspect trace of one item:

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     -e PUID=997     -e PGID=100     -e UMASK=002     ghcr.io/taxel/plextraktsync:latest inspect nnnnnn
PlexTraktSync inspect [0.16.0]
Inspecting nnnnnn: <tmdb:mmmmmmm:<Episode:nnnnnn:Something-(2021)-s01e08>>
URL: https://app.plex.tv/desktop/#!/server/XXXXXXX/details?key=/library/metadata/nnnnnn
Media.Type: episode
Media.Guid: 'plex://episode/XXXXXXX'
Media.Guids: [<Guid:imdb://ttXXXXXXX>, <Guid:tmdb://XXXXXXX>, <Guid:tvdb://XXXXXXX>]
Audio: '5.1', 'English (HE-AAC 5.1)'
Video: 'hevc'
Guids:
  Guid: tmdb://XXXXXXX, Id: XXXXXXX, Provider: tmdb
  Guid: tvdb://XXXXXXX, Id: XXXXXXX, Provider: tvdb
  Guid: imdb://ttXXXXXXX, Id: ttXXXXXXX, Provider: imdb
Metadata: {'collected_at': '2021-11-05:T04:21:24.000Z', 'media_type': 'digital', 'resolution': 'hd_1080p', 'audio': 'aac', 'audio_channels': '5.1'}
Trakt: https://trakt.tv/episodes/XXXXXXX
Watched on Plex: True
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/app/plex_trakt_sync/__main__.py", line 16, in <module>
    cli()
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1659, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/app/plex_trakt_sync/commands/inspect.py", line 61, in inspect
    print(f"Watched on Trakt: {m.watched_on_trakt}")
  File "/app/plex_trakt_sync/media.py", line 77, in watched_on_trakt
    watched = self.trakt_api.watched_shows
  File "/app/plex_trakt_sync/decorators/nocache.py", line 12, in inner
    return method(*args, **kwargs)
  File "/app/plex_trakt_sync/decorators/rate_limit.py", line 23, in wrapper
    return fn(*args, **kwargs)
  File "/app/plex_trakt_sync/trakt_api.py", line 130, in watched_shows
    return pytrakt_extensions.allwatched()
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 552, in inner
    json_data = self._handle_request('get', url)
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 532, in _handle_request
    json_data = json.loads(response.content.decode('UTF-8', 'ignore'))
  File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Workarounds

None found so far

Install method

docker-compose

Version

0.16.0

Python Version

3.10.0

Operating System and Version

Docker inside LXC priviledge container on Proxmox

glensc commented 3 years ago

Unrelated to the bug report, but you can drop these:

 -e PUID=997 -e PGID=100 -e UMASK=002

these have no meaning in this project docker image.

glensc commented 3 years ago

Seems the problem is given by trakt.tv site, seems query to your watched_shows is failing. trakt is not giving json response back. perhaps debug log can help?

typhoe commented 3 years ago

Hi,

and thank you for answering.

I'll drop the uid/gid/umask env setting then.

Regarding debug mode, after enabling it from the config.json file :

root@docker:~# docker run --rm     --name plextraktsync-dryrun     --net=media-net     -v /volume1/data/docker/plextraktsync/config:/app/config     -v /etc/localtime:/etc/localtime:ro     -v /etc/timezone:/etc/timezone:ro     ghcr.io/taxel/plextraktsync
INFO: PlexTraktSync [0.16.0]
INFO: Syncing with Plex XXXX and Trakt XXXX
Sync Movies: True
Sync Shows: True
Plex Server version: 1.24.5.5173-8dcc73a59, updated at: 2021-11-01 03:53:15
Server has 11 libraries: [XXXX]
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/app/plex_trakt_sync/__main__.py", line 16, in <module>
    cli()
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1637, in invoke
    super().invoke(ctx)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/app/plex_trakt_sync/cli.py", line 23, in cli
    sync()
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.10/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/app/plex_trakt_sync/commands/sync.py", line 123, in sync
    sync_all(walker=w, plex=plex, runner=factory.sync(), dry_run=dry_run)
  File "/app/plex_trakt_sync/commands/sync.py", line 19, in sync_all
    runner.sync(walker, dry_run=dry_run)
  File "/app/plex_trakt_sync/sync.py", line 64, in sync
    if self.config.trakt_to_plex["watchlist"] and trakt.watchlist_movies:
  File "/app/plex_trakt_sync/decorators/nocache.py", line 12, in inner
    return method(*args, **kwargs)
  File "/app/plex_trakt_sync/decorators/rate_limit.py", line 23, in wrapper
    return fn(*args, **kwargs)
  File "/app/plex_trakt_sync/trakt_api.py", line 137, in watchlist_movies
    return self.me.watchlist_movies
  File "/app/plex_trakt_sync/decorators/nocache.py", line 12, in inner
    return method(*args, **kwargs)
  File "/app/plex_trakt_sync/decorators/rate_limit.py", line 23, in wrapper
    return fn(*args, **kwargs)
  File "/app/plex_trakt_sync/trakt_api.py", line 75, in me
    return trakt.users.User('me')
  File "/usr/local/lib/python3.10/site-packages/trakt/users.py", line 222, in __init__
    self._get()
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 552, in inner
    json_data = self._handle_request('get', url)
  File "/usr/local/lib/python3.10/site-packages/trakt/core.py", line 532, in _handle_request
    json_data = json.loads(response.content.decode('UTF-8', 'ignore'))
  File "/usr/local/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

cat last_update.log
2021-11-05 16:15:11,069 DEBUG[requests_cache.backends]:Initializing backend: None /app/config/trakt_cache
2021-11-05 16:15:11,069 DEBUG[requests_cache.backends.base]:Initializing SQLitePickleDict with serializer: <requests_cache.serializers.pipeline.SerializerPipeline object at 0x7fd805536bf0>
2021-11-05 16:15:11,070 DEBUG[requests_cache.backends.sqlite]:Opening connection to /app/config/trakt_cache.sqlite:responses
2021-11-05 16:15:11,084 DEBUG[requests_cache.backends.base]:Initializing SQLiteDict with serializer: <requests_cache.serializers.pipeline.SerializerPipeline object at 0x7fd805536bf0>
2021-11-05 16:15:11,084 DEBUG[requests_cache.backends.sqlite]:Opening connection to /app/config/trakt_cache.sqlite:redirects
2021-11-05 16:15:11,312 INFO[PlexTraktSync]:PlexTraktSync [0.16.0]
2021-11-05 16:15:11,327 INFO[PlexTraktSync]:Syncing with Plex XXXXXXXX and Trakt XXXXXXXX
2021-11-05 16:15:11,328 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/
2021-11-05 16:15:11,328 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/
2021-11-05 16:15:11,331 DEBUG[urllib3.connectionpool]:Starting new HTTPS connection (1): plex.XXXXXXXX.com:443
2021-11-05 16:15:11,369 DEBUG[urllib3.connectionpool]:https://plex.XXXXXXXX.com:443 "GET / HTTP/1.1" 200 4078
2021-11-05 16:15:11,369 DEBUG[requests_cache.session]:Pre-cache checks for response from https://plex.XXXXXXXX.com:443/: {'disabled cache': True, 'disabled method': False, 'disabled status': False, 'disabled by filter': False, 'disabled by headers or expiration params': False}
2021-11-05 16:15:11,369 DEBUG[requests_cache.session]:Skipping cache write for URL: https://plex.XXXXXXXX.com:443/
2021-11-05 16:15:11,371 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/library
2021-11-05 16:15:11,371 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/library
2021-11-05 16:15:11,377 DEBUG[urllib3.connectionpool]:https://plex.XXXXXXXX.com:443 "GET /library HTTP/1.1" 200 289
2021-11-05 16:15:11,377 DEBUG[requests_cache.session]:Pre-cache checks for response from https://plex.XXXXXXXX.com:443/library: {'disabled cache': True, 'disabled method': False, 'disabled status': False, 'disabled by filter': False, 'disabled by headers or expiration params': False}
2021-11-05 16:15:11,377 DEBUG[requests_cache.session]:Skipping cache write for URL: https://plex.XXXXXXXX.com:443/library
2021-11-05 16:15:11,377 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/library/sections
2021-11-05 16:15:11,377 DEBUG[plexapi]:GET https://plex.XXXXXXXX.com:443/library/sections
2021-11-05 16:15:11,386 DEBUG[urllib3.connectionpool]:https://plex.XXXXXXXX.com:443 "GET /library/sections HTTP/1.1" 200 2277
2021-11-05 16:15:11,387 DEBUG[requests_cache.session]:Pre-cache checks for response from https://plex.XXXXXXXX.com:443/library/sections: {'disabled cache': True, 'disabled method': False, 'disabled status': False, 'disabled by filter': False, 'disabled by headers or expiration params': False}
2021-11-05 16:15:11,387 DEBUG[requests_cache.session]:Skipping cache write for URL: https://plex.XXXXXXXX.com:443/library/sections
2021-11-05 16:15:11,389 DEBUG[trakt.core]:get: https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,389 DEBUG[trakt.core]:headers: {'Content-Type': 'application/json', 'trakt-api-version': '2', 'trakt-api-key': 'XXXMY-API-TOKENXXX', 'Authorization': 'Bearer XXXXXXXXXXXXXXX'}
2021-11-05 16:15:11,389 DEBUG[trakt.core]:method, url :: get, https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,390 DEBUG[urllib3.connectionpool]:Starting new HTTPS connection (1): api-v2launch.trakt.tv:443
2021-11-05 16:15:11,768 DEBUG[urllib3.connectionpool]:https://api-v2launch.trakt.tv:443 "GET /users/me HTTP/1.1" 423 None
2021-11-05 16:15:11,769 DEBUG[requests_cache.session]:Pre-cache checks for response from https://api-v2launch.trakt.tv/users/me: {'disabled cache': True, 'disabled method': False, 'disabled status': True, 'disabled by filter': False, 'disabled by headers or expiration params': False}
2021-11-05 16:15:11,769 DEBUG[requests_cache.session]:Skipping cache write for URL: https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,769 DEBUG[trakt.core]:RESPONSE [get] (https://api-v2launch.trakt.tv/users/me): <Response [423]>

So from http error code from Trakt, it seems the return of the API is "locked"? I'm not VIP on Trakt, is that a problem?

Or should I try to force login again on trakt again from plextraktsync (although "logins" option returns that my logins are ok) ?

glensc commented 3 years ago

Your account is locked:

Locked User Account - have the user contact support

typhoe commented 3 years ago

Ok, thank you!

I'll contact Trakt then, and sorry for the bothering...

glensc commented 3 years ago

@typhoe did you notice this disclaimer on the bug report form?

typhoe commented 3 years ago

@glensc sorry, didn't noticed it, my bad!

Issue closed. The crashs were because my account is locked on Trakt.tv right now.

To see the root cause, you have to enable debug log in the config.json file

"log_debug_messages": true,

and you'll see the error code (423) returned by Trakt.tv api server in the log:

2021-11-05 16:15:11,389 DEBUG[trakt.core]:get: https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,389 DEBUG[trakt.core]:headers: {'Content-Type': 'application/json', 'trakt-api-version': '2', 'trakt-api-key': 'XXXMY-API-TOKENXXX', 'Authorization': 'Bearer XXXXXXXXXXXXXXX'}
2021-11-05 16:15:11,389 DEBUG[trakt.core]:method, url :: get, https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,390 DEBUG[urllib3.connectionpool]:Starting new HTTPS connection (1): api-v2launch.trakt.tv:443
2021-11-05 16:15:11,768 DEBUG[urllib3.connectionpool]:https://api-v2launch.trakt.tv:443 "GET /users/me HTTP/1.1" 423 None
2021-11-05 16:15:11,769 DEBUG[requests_cache.session]:Pre-cache checks for response from https://api-v2launch.trakt.tv/users/me: {'disabled cache': True, 'disabled method': False, 'disabled status': True, 'disabled by filter': False, 'disabled by headers or expiration params': False}
2021-11-05 16:15:11,769 DEBUG[requests_cache.session]:Skipping cache write for URL: https://api-v2launch.trakt.tv/users/me
2021-11-05 16:15:11,769 DEBUG[trakt.core]:RESPONSE [get] (https://api-v2launch.trakt.tv/users/me): <Response [423]>

Trakt.tv API status code can be found here: https://trakt.docs.apiary.io/#introduction/status-codes

And my accound was locked because there was some problem of increasing charge on Trakt.tv server at some point. Trakt.tv made a post on that in their repo: https://github.com/trakt/api-help/issues/228

I was indeed using Trakt.tv to sync multiple instance of Kodi for me and may have trigger the lock on my account at some point. I since migrated to plex and didn't noticed the lock before...

To ask for the lock to be lift, you can go to https://support.trakt.tv/support/home and create a new ticket (I'm still waiting for mine to be traited)

Anyway, the problem was not from PlexTraktSync but from my account state on Trakt.tv, so closing this issue.

glensc commented 3 years ago

Addding some handling to it:

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

which depends on PyTrakt change being released first:

https://github.com/moogar0880/PyTrakt/pull/163

Taxel / PlexTraktSync