ManiMatter / decluttarr

Watches radarr, sonarr, lidarr, readarr and whisparr download queues and removes downloads if they become stalled or no longer needed.
GNU General Public License v3.0
99 stars 15 forks source link

Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'> #63

Closed D34DC3N73R closed 3 months ago

D34DC3N73R commented 3 months ago

I just started decluttarr for the first time and ran into the following error. I saw a comment in #52 asking for a new issue so I opened this one. I will try out verbose logs to see if there is any other details.

$ docker logs -f decluttarr
[INFO]: ##################################################
[INFO]: Decluttarr - Application Started!
[INFO]: 
[INFO]: *** Current Settings ***
[INFO]: Version: v1.31.0
[INFO]: Commit: dca40aa
[INFO]: 
[INFO]: True | Removing failed downloads
[INFO]: True | Removing downloads missing metadata
[INFO]: False | Removing downloads missing files
[INFO]: False | Removing orphan downloads
[INFO]: False | Removing slow downloads
[INFO]: True | Removing stalled downloads
[INFO]: False | Removing downloads belonging to unmonitored TV shows/movies
[INFO]: 
[INFO]: Running every: 0 days 0 hours 10.0 minutes
[INFO]: Permitted number of times before stalled/missing metadata/slow downloads are removed: 3
[INFO]: Downloads with this tag will be skipped: "Keep"
[INFO]: Private Trackers will be skipped: True
[INFO]: 
[INFO]: *** Configured Instances ***
[INFO]: Radarr: http://radarr:7878/api/v3
[INFO]: Sonarr: http://sonarr:8989/api/v3
[INFO]: Lidarr: http://lidarr:8686/api/v1
[INFO]: qBittorrent: http://qbit:8888/api/v2
[INFO]: 
[INFO]: *** Check Instances ***
[INFO]: OK | Radarr
[INFO]: OK | Sonarr
[INFO]: OK | Lidarr
[INFO]: OK | qBittorrent
[INFO]: 
[INFO]: ##################################################
[INFO]: LOG_LEVEL = INFO: Only logging changes (switch to VERBOSE for more info)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[INFO]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[INFO]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)

Verbose Logs:

[INFO   ]: ##################################################
[INFO   ]: 
[VERBOSE]: --------------------------------------------------
[VERBOSE]: Cleaning queue on Radarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Sonarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Lidarr:
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[INFO   ]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (1 out of 3 permitted times): Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: 
[VERBOSE]: Queue clean-up complete!
[VERBOSE]: --------------------------------------------------
[VERBOSE]: Cleaning queue on Radarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Sonarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Lidarr:
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[INFO   ]: >>> Detected stalled download (2 out of 3 permitted times): Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (2 out of 3 permitted times): Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (2 out of 3 permitted times): Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: 
[VERBOSE]: Queue clean-up complete!
[VERBOSE]: --------------------------------------------------
[VERBOSE]: Cleaning queue on Radarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Sonarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Lidarr:
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[INFO   ]: >>> Detected stalled download (3 out of 3 permitted times): Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (3 out of 3 permitted times): Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download (3 out of 3 permitted times): Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: 
[VERBOSE]: Queue clean-up complete!
[VERBOSE]: --------------------------------------------------
[VERBOSE]: Cleaning queue on Radarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Sonarr:
[VERBOSE]: >>> Queue is clean.
[VERBOSE]: Cleaning queue on Lidarr:
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[INFO   ]: >>> Detected stalled download too many times (4 out of 3 permitted times): Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download too many times (4 out of 3 permitted times): Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO   ]: >>> Detected stalled download too many times (4 out of 3 permitted times): Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[INFO   ]: >>> Removing stalled download: Xxxtentacion - NA (2018 - Hip Hop Rap) [Flac 16-44]
[INFO   ]: >>> Removing stalled download: Xxxtentacion - Bad Vibes Forever (2019 - Pop) [Flac 16-44]
[INFO   ]: >>> Removing stalled download: Xxxtentacion - SKINS (2018 - Pop) [Flac 16-44]
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[VERBOSE]: 
[VERBOSE]: Queue clean-up complete!

The stalled torrents were removed from qbit. I'm not sure if there is an API issue with lidarr, but it does seem to work as intended. Removed downloads were not immediately removed from lidarr queue, but replacement downloads had already been searched by the time the queue refreshed.

ManiMatter commented 3 months ago

Thank you for the details.

could you please 1) switch to ‚DEBUG‘ logs 2) turn off all features but one that causes the issue 3) if it‘s lidarr related, remove radarr/sonarr/readarr 4) submit logs to a pastebin

this would give us way more logs and remove unecessary logs

thank you

D34DC3N73R commented 3 months ago

Maybe I'm not running this right but this is my docker-compose

  decluttarr-debug:
    image: ghcr.io/manimatter/decluttarr:latest
    container_name: decluttarr-debug
    restart: unless-stopped
    environment:
      - TZ=$TZ
      - PUID=$PUID
      - PGID=$PGID
      ## General
      - LOG_LEVEL=DEBUG
      #- TEST_RUN=True
      #- SSL_VERIFICATION=False
      ## Features 
      - REMOVE_TIMER=10
      - REMOVE_FAILED=True
      - REMOVE_METADATA_MISSING=True
      - REMOVE_MISSING_FILES=False
      - REMOVE_ORPHANS=False
      - REMOVE_SLOW=False
      - REMOVE_STALLED=True
      - REMOVE_UNMONITORED=False
      - MIN_DOWNLOAD_SPEED=100
      - PERMITTED_ATTEMPTS=3
      - NO_STALLED_REMOVAL_QBIT_TAG=Keep
      - IGNORE_PRIVATE_TRACKERS=True
      ## Lidarr
      - LIDARR_URL=http://lidarr:8686
      - LIDARR_KEY=$LIDARR_KEY
      ## qBittorrent
      - QBITTORRENT_URL=http://qbit:8888
      - QBITTORRENT_USERNAME=$QBIT_UN
      - QBITTORRENT_PASSWORD=$QBIT_PW

The container constantly restarts with these logs

 $ docker logs -f decluttarr-debug
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
$

Edit, it appears the container won't run with just lidarr configured. These are debug logs with radarr and sonarr as well as lidarr https://hastebin.com/share/lepamajezi.markdown

ManiMatter commented 3 months ago

Thank you. I‘ll try to look into it on the weekend.

ManiMatter commented 3 months ago

ok few questions: 1) let's does it run if you only have either radarr or sonarr running together with lidarr? or do you need both so that the container starts? 2) can you please pull the "dev" version instead of the "latest" version and repaste the logs? I added logs hoping to understanding better what's going on. 3) Which lidarr version are you using?

I will probably need to ask you a few more times to pull logs, please bear with me

D34DC3N73R commented 3 months ago

:latest w/ Sonarr + Lidarr: TypeError: unsupported operand type(s) for +: 'dict' and 'dict' :latest w/ Radarr + Lidarr: Container starts

I'm not able to pull the dev image. (image: ghcr.io/manimatter/decluttarr:dev)

$ docker compose pull decluttarr
[+] Pulling 0/1
 ⠼ decluttarr Pulling                                                                                                                             1.4s 
manifest unknown

There only appears to be a single image on github and there are no tags in docker hub.

edit: lidarr 2.1.7.4030-ls161 by linuxserver.io pulled using lscr.io/linuxserver/lidarr

edit2: Cloned the dev branch and built the dev image

:dev w/ only Lidarr: TypeError: unsupported operand type(s) for +: 'dict' and 'dict' :dev w/ Sonarr + Lidarr: TypeError: unsupported operand type(s) for +: 'dict' and 'dict' :dev w/ Radarr + Lidarr: Container starts

dev built image with debug logs using radar + lidarr: https://hastebin.com/share/ukohivohad.bash (cleaned up the download waiting to be imported in lidarr)

ManiMatter commented 3 months ago

This gets worse and worse 🤷‍♂️ Weekend work! Thx for the help thus far

ManiMatter commented 3 months ago

you should now again be able to pull images. Quick Q: does sonarr alone start?

D34DC3N73R commented 3 months ago

No. With lidarr and radarr commented out, I get the same logs

$ docker logs -f decluttarr
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'
TypeError: unsupported operand type(s) for +: 'dict' and 'dict'

Decluttarr : dev image Sonarr: 4.0.2.1183-ls231 Radarr: 5.3.6.8612-ls210 Lidarr: 2.1.7.4030-ls162

ManiMatter commented 3 months ago

Super! I was hoping that‘d be the case. Will start digging

ManiMatter commented 3 months ago

I think I solved it. Could you please try to pull the dev image and verify?

D34DC3N73R commented 3 months ago

The container now starts with just lidarr (and just sonarr as well) configured. Dev w/ only lidarr - debug logs: https://hastebin.com/share/ciwogobali.bash

ManiMatter commented 3 months ago

Hm. I think we are on to something here

The below code shows that the lidarr queue API was successfully hit, but the response does not have the 'downloadId' key in it. According to the Lidarr API spec that should be there though.

[DEBUG]: http://lidarr:8686 "GET /api/v1/queue?page=1&pageSize=1 HTTP/1.1" 200 None
[WARNING]: >>> Queue cleaning failed on formattedQueueInfo. (File: shared.py / Line: 128 / Error Message: 'downloadId' / Error Type: <class 'KeyError'>)
[DEBUG]: KeyError: 'downloadId'

[DEBUG]: formattedQueueInfo/queue for debug: {'page': 1, 'pageSize': 1, 'sortKey': 'timeleft', 'sortDirection': 'descending', 'totalRecords': 1, 'records': [{'artistId': 492, 'albumId': 4535, 'quality': {'quality': {'id': 4, 'name': 'MP3-320'}, 'revision': {'version': 1, 'real': 0, 'isRepack': False}}, 'customFormats': [], 'customFormatScore': 0, 'size': 98481208, 'title': 'Buddy   Harlan & Alondra (2018) Mp3 (320kbps) [Hunter]', 'sizeleft': 98481208, 'timeleft': '00:04:38.2148902', 'estimatedCompletionTime': '2024-03-29T17:34:50Z', 'added': '2024-02-23T01:10:54Z', 'status': 'delay', 'protocol': 'torrent', 'downloadClientHasPostImportCategory': False, 'indexer': '1337x (Prowlarr)', 'trackFileCount': 12, 'trackHasFileCount': 12, 'downloadForced': False, 'id': 1177655784}]}

Will try to find somebody from lidarr and ask Update: Just did, and we need your help in reproducing this.

Is there any reason that you can think of why this particular item would not have a downloadId? This happens on qBittorrent, right? which qbit version are you using, and which image?

D34DC3N73R commented 3 months ago

Lidarr 2.1.7.4030-ls162 (lscr.io/linuxserver/lidarr) qBittorrent: v4.6.3 (binhex/arch-qbittorrentvpn)

Yes, that particular torrent likely doesn't have a download id because the torrent is currently 'pending' due to delay profiles in Lidarr.

Edit: with that torrent completed, the logs look as intended, although there are currently no downloading items in lidarr

[DEBUG]: Starting new HTTP connection (1): qbit:8888
[DEBUG]: http://qbit:8888 "GET /api/v2/torrents/info HTTP/1.1" 200 8252
[VERBOSE]: Cleaning queue on Lidarr:
[DEBUG]: Starting new HTTP connection (1): lidarr:8686
[DEBUG]: http://lidarr:8686 "POST /api/v1/command HTTP/1.1" 201 None
[DEBUG]: Starting new HTTP connection (1): lidarr:8686
[DEBUG]: http://lidarr:8686 "GET /api/v1/queue?includeUnknownArtistItems=True HTTP/1.1" 200 None
[VERBOSE]: >>> Queue is empty.
[VERBOSE]: 
[VERBOSE]: Queue clean-up complete!
ManiMatter commented 3 months ago

I wasn't even aware of the delayed profiles - functionality. learnt something new.

I just added a piece of code that should hopefully deal with those delayed items.

Are you able to again create a delayed lidarr-download, pull the "dev" version I just uploadeded, and post the logs (on debug level)? Hopefully you should not encounter any problems anymore.

D34DC3N73R commented 3 months ago

I seem to be running into a different error now that forces the container to exit.

[DEBUG]: Using selector: EpollSelector
[DEBUG]: Starting new HTTP connection (1): lidarr:8686
[DEBUG]: http://lidarr:8686 "GET /api/v1/system/status HTTP/1.1" 200 None
[INFO]: ##################################################
[INFO]: Decluttarr - Application Started!
[INFO]: 
[INFO]: *** Current Settings ***
[INFO]: Version: dev
[INFO]: Commit: 5f0a218
[INFO]: 
[INFO]: True | Removing failed downloads
[INFO]: True | Removing downloads missing metadata
[INFO]: False | Removing downloads missing files
[INFO]: False | Removing orphan downloads
[INFO]: False | Removing slow downloads
[INFO]: True | Removing stalled downloads
[INFO]: False | Removing downloads belonging to unmonitored items
[INFO]: 
[INFO]: Running every: 0 days 0 hours 10.0 minutes
[INFO]: Permitted number of times before stalled/missing metadata/slow downloads are removed: 3
[INFO]: Downloads with this tag will be skipped: "Keep"
[INFO]: Private Trackers will be skipped: True
[INFO]: 
[INFO]: *** Configured Instances ***
[INFO]: Lidarr: http://lidarr:8686/api/v1
[INFO]: qBittorrent: http://qbit:8888/api/v2
[INFO]: 
[INFO]: *** Check Instances ***
[DEBUG]: Starting new HTTP connection (1): lidarr:8686
[DEBUG]: http://lidarr:8686 "GET /api/v1/system/status HTTP/1.1" 200 None
[INFO]: OK  | Lidarr
UnboundLocalError: local variable 'current_version' referenced before assignment

The delay profiles are super helpful if you have private indexers. I prefer to dl what I can from usenet, but often the releases will first appear on private indexers, so I have delays in all the 'arrs. If the content doesn't show up within 12 hours, the torrent is processed, otherwise, the nzb will take priority and remove the torrent from pending.

ManiMatter commented 3 months ago

I am so sorry for the back and forth. I just uploaded a new version that should fix also the current_version problem. Refactored quite a bit of code yesterday when trying to find the dict + dict problem, and by doing so I seem to have added this new bug... sorry for that.

thanks for the explanation on the delay profiles and the new logs.

D34DC3N73R commented 3 months ago

The dev container now starts fine. From what I can gather, manually searched items don't adhere to the delay profiles. I believe they have to be from the RSS search. So, I haven't been able to get one from lidarr yet, but I do have some delayed downloads in sonarr so I've captured those debug logs: https://hastebin.com/share/iqedixisaz.markdown

I trimmed them a bit, but let me know if you need more.

ManiMatter commented 3 months ago

Not sure I understand your reference to RSS searched items.

From the logs, things look as if they are running fine now. Are you still experiencing any issues? The additition from yesterday seems to work (">>> Delayed queue item ignored: ...")

D34DC3N73R commented 3 months ago

There are 3 types of searches in the arrs. Interactive search where you pick the download, automatic search where the arr picks the download, and RSS which really isn't a search, but rather an RSS list of all torrents from every indexer that is parsed by the arrs. If something in your wanted list matches a parsed torrent from the RSS feed, it's added to the download queue. The RSS parsed torrents seem to be the only method that utilizes delay profiles.

With that said, it does appear to be working as intended and I haven't seen any errors. If you want to close this, that's fine with me. I can open a different issue if I notice anything when lidarr does pick up a delayed torrent.

ManiMatter commented 3 months ago

understood.

in theory, the way i implemented it should be agnostic about the method and should work in all 3 methods.

thanks for your help with debugging this.

quick one: i just pushed a (hopefully final) version, would you mind to once again post the logs of sonarr ? just want to make sure it works as expected, then will merge to the "latest"

D34DC3N73R commented 3 months ago

sure thing. here are the full logs from a startup with just sonarr enabled on the most recent dev image https://hastebin.com/share/avimemipay.markdown

ManiMatter commented 3 months ago

Looks splendid. thanks for the help.

Merging to latest now and suggest we close this ticket, unless you need help with anything else?

D34DC3N73R commented 3 months ago

sounds good. If I notice anything else I'll open a new ticket. Thanks for the help!