blackhole: arr not working (sporadically)

[d3mystified]

Similar to #2 (comment). Another log example:

[2024-06-11 23:20:51.263356] [RealDebridMagnet] [The.Big.Red.One.1980.1080p.BluRay.REMUX.AVC.FLAC.2.0-OlSTiLe] Failing
[2024-06-11 23:20:51.267348] [The.Big.Red.One.1980.1080p.BluRay.REMUX.AVC.FLAC.2.0-OlSTiLe] Error processing The.Big.Red.One.1980.1080p.BluRay.REMUX.AVC.FLAC.2.0-OlSTiLe
[2024-06-11 23:20:51.267370] [The.Big.Red.One.1980.1080p.BluRay.REMUX.AVC.FLAC.2.0-OlSTiLe] Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/requests/models.py", line 971, in json
    return complexjson.loads(self.text, **kwargs)
  File "/usr/local/lib/python3.8/json/__init__.py", line 357, in loads
    return _default_decoder.decode(s)
  File "/usr/local/lib/python3.8/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/local/lib/python3.8/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)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/app/blackhole.py", line 306, in processFile
    fail(torrent, arr)
  File "/app/blackhole.py", line 326, in fail
    history = arr.getHistory(blackhole['historyPageSize'])['records']
  File "/app/shared/arr.py", line 205, in getHistory
    history = historyRequest.json()
  File "/usr/local/lib/python3.8/site-packages/requests/models.py", line 975, in json
    raise RequestsJSONDecodeError(e.msg, e.doc, e.pos)
requests.exceptions.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

[2024-06-11 23:20:51.267662] Exit 'on_created'
[2024-06-11 23:39:27.675085] Enter 'on_created'
[2024-06-11 23:39:27.675108] radarr/sonarr: radarr

However this is not happening consistently. In the last 8 hours, radarr grabbed 13 items (all were symlinked successfully) but only 2 were imported by radarr. Similar numbers for sonarr.

So this is not a configuration issue or a permanent bug since this is sometimes working. I also don't think my arr's are crashing because I have uptime monitoring.

Here's the env I'm using:

SERVER_DOMAIN=https://internal.server.url

PLEX_HOST="https://plex.tv/"
PLEX_METADATA_HOST="https://metadata.provider.plex.tv/"
PLEX_SERVER_HOST=https://plex.server.url
PLEX_SERVER_MACHINE_ID=<plex_server_machine_id>
PLEX_SERVER_API_KEY=<plex_server_api_key>
PLEX_SERVER_MOVIE_LIBRARY_ID=<plex_server_movie_library_id>
PLEX_SERVER_TV_SHOW_LIBRARY_ID=<plex_server_movie_library_id>

OVERSEERR_HOST=<overseerr_host>
OVERSEERR_API_KEY=<overseerr_api_key>

SONARR_HOST="http://IP:8991/sonarr"
SONARR_API_KEY=key

RADARR_HOST="http://IP:7880/radarr"
RADARR_API_KEY=key

TAUTULLI_HOST=<tautulli_host>
TAUTULLI_API_KEY=<tautulli_api_key>

REALDEBRID_HOST="https://api.real-debrid.com/rest/1.0/"
REALDEBRID_API_KEY=RD_KEY

TRAKT_API_KEY=<trakt_api_key>

WATCHLIST_PLEX_PRODUCT=<watchlist_plex_product>
WATCHLIST_PLEX_VERSION=<watchlist_plex_version>
WATCHLIST_PLEX_CLIENT_IDENTIFIER=<watchlist_plex_client_identifier>

BLACKHOLE_BASE_WATCH_PATH="/debrid/blackhole"
BLACKHOLE_RADARR_PATH="radarr"
BLACKHOLE_SONARR_PATH="sonarr"
BLACKHOLE_FAIL_IF_NOT_CACHED=true
BLACKHOLE_RD_MOUNT_REFRESH_SECONDS=120
BLACKHOLE_RD_MOUNT_TORRENTS_PATH="/data/debrid-rd/torrents"
BLACKHOLE_WAIT_FOR_TORRENT_TIMEOUT=120
BLACKHOLE_HISTORY_PAGE_SIZE=200

DISCORD_ENABLED=false
DISCORD_UPDATE_ENABLED=false
DISCORD_WEBHOOK_URL=<discord_webhook_url>

PYTHONUNBUFFERED=TRUE

I'm not sure what's going on here - it could be that the issue is transient. But the script doesn't log the response the arr's return so it's hard to say. I can see 2 things that may help figure this out:

1. Log (maybe as a trace level) the arr response if it's not 200.
2. Retry arr calls if they are 500-class errors.

[d3mystified]

I tried to repro this in the blackhole container (docker exec -it blackhole bash -> python):

import requests

host="same_as_env"
key="same_as_env"

status_code_counts = {}
for _ in range(100):
    response = requests.get(f"{host}/api/v3/history?pageSize=200&apiKey={key}")
    if response.status_code not in status_code_counts:
      status_code_counts[response.status_code] = 0
    status_code_counts[response.status_code] += 1

The final result is:

>>> print(status_code_counts)
{200: 100}

I'm now even more unsure of what's going on. I've tried this over a 1000 runs and I only get 200 status codes.

EDIT:

I also checked with host containing a trailing / and the result is still response code 200 (but the response.text contains radarr html and response.json() fails with the JSONDecodeError. So this issue may not be resolved by checking return codes but rather with a try.. except.

This still doesn't help with why this is happening only sometimes though.

[d3mystified]

Another test I did that better captures what app.py is doing:

>>> json_count = { "json": 0, "notJson": 0 }
>>> for _ in range(100):
...     response = requests.get(f"{host}/api/v3/history?pageSize=200&apiKey={key}")
...     try:
...       null = response.json()
...       json_count["json"] += 1
...     except:
...       json_count["notJson"] += 1
...
>>> print(json_count)
{'json': 100, 'notJson': 0}

So the container is able to reach the arr's just fine, but blackhole for some reason isn't still getting json response back.