SABnzbd Sonarr response: started instead of Sonarr response: queued.

[DamenQuixotic]

@mdhiggins Im running into this issue now also, but its not constant its random :

_Originally posted by @SudoUser-Sam in https://github.com/mdhiggins/sickbeard_mp4_automator/issues/881#issuecomment-553248224_

---

I am still encounting this exact issue. Its random when it happens but if I download a season/multiple seasons of a show many of them end up with this result. If they get the "started" response Sonarr never picks them up. If I keep retrying to search for the missing episodes they will eventually all work but that's kinda against the point of MP4 Automator to have to babysit it.

[DamenQuixotic]

Here is the preview of a failed script call from SAB side.

2020-08-14 17:39:57 - resources.mediaprocessor - INFO - Starting conversion.
2020-08-14 17:39:57 - resources.mediaprocessor - INFO - FFmpeg command:
2020-08-14 17:39:57 - resources.mediaprocessor - INFO - ======================
2020-08-14 17:39:57 - resources.mediaprocessor - INFO - C:\FFMPEG\bin\ffmpeg.exe -i C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].mp4.original -vcodec copy -map 0:0 -metadata:s:v title=HD -c:a:0 copy -map 0:1 -metadata:s:a:0 title=Stereo -metadata:s:a:0 language=und -disposition:a:0 +default-dub-original-comment-lyrics-karaoke-forced-hearing_impaired-visual_impaired-captions -f mp4 -threads 0 -metadata:g encoding_tool=SMA -y C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].mp4
2020-08-14 17:39:57 - resources.mediaprocessor - INFO - ======================
2020-08-14 17:39:58 - resources.mediaprocessor - INFO - C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].mp4 created.
2020-08-14 17:39:58 - SABPostProcess - INFO - Successfully processed C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].mp4.
2020-08-14 17:39:58 - SABPostProcess - INFO - Passing C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3 directory to Sonarr.
2020-08-14 17:39:58 - autoprocess.sonarr - INFO - Sonarr notifier started.
2020-08-14 17:39:58 - autoprocess.sonarr - INFO - Requesting Sonarr to scan directory 'C:\Users\Media Server\Downloads\sabnzbd\complete\[DeadFish] Boruto- Naruto Next Generations - 111 [720p][AAC].3'.
2020-08-14 17:39:58 - autoprocess.sonarr - INFO - Sonarr response: started.

[mdhiggins]

Can you post some debug level logging as well as Sonarr's logs for when this doesn't work? And are you on sonarr v2 or v3?

The log you posted for the failed script call isn't helpful it doesn't include any of the sonarr relevant information appears to be truncated, I need the whole log which is found in sma.log and specifically with debug level logging which is set via logging.ini in your script folder

[DamenQuixotic]

Can you post some debug level logging as well as Sonarr's logs for when this doesn't work? And are you on sonarr v2 or v3?

The log you posted for the failed script call isn't helpful it doesn't include any of the sonarr relevant information appears to be truncated, I need the whole log which is found in sma.log and specifically with debug level logging which is set via logging.ini in your script folder

Yes sorry, was trying to figure out how to post the whole thing. I have switched on debug logging for sonarr and going to try to get the relevant parts for a failed one.

[mdhiggins]

Alright the log is better but you have to understand its just an api call with little information given on the return

https://github.com/Sonarr/Sonarr/wiki/Command

From that point on you need to pull Sonarr logs to see why sonarr is failing to complete the task because its out of the script's hand at that point

[mdhiggins]

And the sma debug level logging that is set via logging.ini in the config folder of the script, looks like its not enabled currently based on what you posted

[DamenQuixotic]

Alright the log is better but you have to understand its just an api call with little information given on the return

https://github.com/Sonarr/Sonarr/wiki/Command

From that point on you need to pull Sonarr logs to see why sonarr is failing to complete the task because its out of the script's hand at that point

What I don't quite get is why the script is outputting "started" instead of "queued" though. Because when they work there is never a started line, just goes straight to queued.

For the logging.ini I am not sure what exact logger to set to debug. Current file looks like:

[loggers] keys = root, manual, nzbget

[handlers] keys = consoleHandler, nzbgetHandler, fileHandler, manualHandler

[formatters] keys = simpleFormatter, minimalFormatter, nzbgetFormatter

[logger_root] level = DEBUG handlers = consoleHandler, fileHandler

[logger_nzbget] level = DEBUG handlers = nzbgetHandler, fileHandler propagate = 0 qualname = NZBGetPostProcess

[logger_manual] level = DEBUG handlers = manualHandler, fileHandler propagate = 0 qualname = MANUAL

[handler_consoleHandler] class = StreamHandler level = INFO formatter = simpleFormatter args = (sys.stdout,)

[handler_nzbgetHandler] class = StreamHandler level = INFO formatter = nzbgetFormatter args = (sys.stdout,)

[handler_manualHandler] class = StreamHandler level = INFO formatter = minimalFormatter args = (sys.stdout,)

[handler_fileHandler] class = handlers.RotatingFileHandler level = INFO formatter = simpleFormatter args = ('%(logfilename)s', 10000, 1)

[formatter_simpleFormatter] format = %(asctime)s - %(name)s - %(levelname)s - %(message)s datefmt = %Y-%m-%d %H:%M:%S

[formatter_minimalFormatter] format = %(message)s datefmt =

[formatter_nzbgetFormatter] format = [%(levelname)s] %(message)s datefmt =

[mdhiggins]

The script is just printing sonarr's response to the command. Whenever you run a command with sonarr it responds with a json object that looks like of like this

{
  "name": "RescanSeries",
  "startedOn": "0001-01-01T00:00:00Z",
  "stateChangeTime": "2014-02-05T05:09:09.2366139Z",
  "sendUpdatesToClient": true,
  "state": "pending",
  "id": 24
}

and the script is just printing the state part of that result. It has no control over what that response is

and for logging.ini change in the handler_fileHandler

[handler_fileHandler]
class = handlers.RotatingFileHandler
level = DEBUG
formatter = simpleFormatter
args = ('%(logfilename)s', 10000, 1)

[mdhiggins]

Setting debug in logging.ini will only show the a little more info like what I posted above, the real helpful info will be checking inside Sonarr to see what happens after that command is issued that's responding with start to find out what its doing and why its not behaving as you'd expect

[DamenQuixotic]

Okay, I am just going to try a few batches to get the problem to come up. Sadly it doesn't happen every time. I will update with some Sonarr logs once I get it to come up here.

[mdhiggins]

You can probably use the id that gets included in Sonarr's response (which will be visible with debug logging) to help track down the relevant components inside Sonarr's logs, just a tip

[morpheus2n2]

@DamenQuixotic Can I ask what your system setup is as I used to have this problem.

[DamenQuixotic]

Not sure exactly what you are asking for, like the PC specs or the combination of programs I am using?

[morpheus2n2]

Both :)

[DamenQuixotic]

Windows 10 Pro 64bit Mobo: B365M DS3H CPU: Intel i5 9600k GPU: N/A

Sonarr > NZBGet/SABnzbd > Sonarr > Plex

Originally came across this issue while using SABnzbd but am now trying NZBGet to see if I can get it here too.

[mdhiggins]

I'm sure NZBGet will have the same issue since it uses the exact same code to notify Sonarr Hopefully between the two of you we can some Sonarr logs for a started response to see what's going on

And I still don't know what version of Sonarr we're talking about, v2 or v3 (and specific version would be good to know too if you can get the logged event)

[DamenQuixotic]

I am using V2 of sonarr myself.

[morpheus2n2]

Ok how much Ram? Cos I think this the same problem I had

[DamenQuixotic]

16GB of RAM.

[morpheus2n2]

Ok yeah think its the same problem I had then, basically I pined it down to a problem with SAB and Sonarr communicating properly when the system is under load, So basically your running a system that's a little bit more powerful then my old one where this was a problem, however on my new system it has happened only once and that was when I was stress testing the CPU.

In plain english this is what I put it down to as it made sense and seemed to add up perfectly when testing. What I think it is, is SMA (this script) sends the command to Sonarr to pick up the file however when it then asks Sab to release said file its basically told nope still using it go away, so Sonarr will just not pick up the file SMA thinks all's good cos it told sonarr what to do, but Sonarr and Sab don't agree with each other at the same time. I am almost certain its CPU interrupts at the route of it all.

[DamenQuixotic]

Hm, I wonder if I can tell NZBGet to add a delay in between post processing. It already only does one at a time, but if the file is already MP4 and skips the convert it does do them pretty quickly back to back.

What you're saying does make sense because it only happens when adding like whole seasons of a show and never when I only queue up a couple at a time.

Or what would be nice is if it got the "started" response back from sonarr to just have it try again maybe. I know I can rerun post processing with NZBGet but the job doesn't technically get flagged as failed so it's hard to tell which ones run into this problem. On top of failing the job might cause sonarr to try another download since I use failed download handling. It's a tricky problem...

[mdhiggins]

I actually would speculate that it has nothing to do with cpu load and probably is some weird quirk where the API has been asked to scan the same directory already (maybe from a previous job) and is currently scanning said directory, so sonarr instead says 'started' because it thinks the job is already in progress as opposed to queueing the new request like its supposed (and returning 'queued').

Higher cpu load might make these scans slower and more likely to still be in progress when the next request to the API happens which might be why you're noticing it in those circumstances

This would also make sense in batch jobs which are likely to point to shared directories with multiple files being processed in rapid succession

If we can get some logs that show what's happening then I can write some custom code to wait try the API call again if a 'started' response is received instead of queued but we need to confirm that theory with some logs first otherwise it might just create more problems

[mdhiggins]

Even some debug logs that show the id of multiple API calls in rapid succession to see if the id matches a previously queued job would be very useful

[DamenQuixotic]

Okay, so I deleted all the episodes for a series and told Sonarr to go get them again.

I see some Sonarr response: started but I am honestly not sure what information in these logs in relevant and I am sure some stuff in here I don't want to just dump in a public pastebin because debug logging logs some sensitive stuff I believe.

What is the best way to know what information you need / how to get it to you?

[mdhiggins]

For SMA in the sma.log file: Just before the print of 'Sonarr response: started' there should be a JSON object that gets printed (assuming debug logging is enabled) Should look something like this (it may not be formatted as nicely, might be on a single line)

{
  "name": "downloadedepisodesscan",
  "startedOn": "0001-01-01T00:00:00Z",
  "stateChangeTime": "2014-02-05T05:09:09.2366139Z",
  "sendUpdatesToClient": true,
  "state": "started",
  "id": 24
}

That code comes from these 2 lines in autoprocess/sonarr.py

        log.debug(rstate)
        log.info("%sSonarr response: %s." % (infoprefix, rstate['state']))

And with regards to the logs inside Sonarr, you're kind of on your own but I would look for anything about an API request for 'downloadedepisodesscan' being started. The ID that's printed (like in the sample above) hopefully will be included in the Sonarr logs and should match

You're also free to email me part of the logs (though please don't send massive pages of unrelated stuff) if you don't want to publicly post them but want me to take a look

[mdhiggins]

The sonarr logs may need to be set to debug or trace as well in order to see something that gives info related to this

That can be set in the sonarr settings

[DamenQuixotic]

(Sidenote I have no clue how to format line returns in the code block here, if you have any tips let me know)

I might have to switch Sonarr to trace, searching by the ID returned in the whole log folder for sonarr doesn't return anything.

But here is something that may prove one of your points. If we look at the response object of one that gets "started" it has a couple keys that a "queued" one doesn't.

stateChangeTime and started.

Here is a "started" one:

2020 - 08 - 16 19: 45: 48 - autoprocess.sonarr - DEBUG - {
    'name': 'DownloadedEpisodesScan',
    'body': {
        'sendUpdatesToClient': False,
        'sendUpdates': False,
        'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E04.WEB.h264-WALT-xpost',
        'importMode': 'auto',
        'updateScheduledTask': True,
        'completionMessage': 'Completed',
        'name': 'DownloadedEpisodesScan',
        'trigger': 'manual'
    },
    'priority': 'normal',
    'status': 'started',
    'queued': '2020-08-17T00:45:38.4272724Z',
    'started': '2020-08-17T00:45:38.4292662Z',
    'trigger': 'manual',
    'state': 'started',
    'manual': True,
    'startedOn': '2020-08-17T00:45:38.4272724Z',
    'stateChangeTime': '2020-08-17T00:45:38.4292662Z',
    'sendUpdatesToClient': False,
    'updateScheduledTask': True,
    'id': 11974
}
2020 - 08 - 16 19: 45: 48 - autoprocess.sonarr - INFO - [INFO] Sonarr response: started.

And here is a queued one:

2020 - 08 - 16 19: 45: 53 - autoprocess.sonarr - DEBUG - {
    'name': 'DownloadedEpisodesScan',
    'body': {
        'sendUpdatesToClient': False,
        'sendUpdates': False,
        'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E07.WEB.h264-WALT-xpost',
        'importMode': 'auto',
        'updateScheduledTask': True,
        'completionMessage': 'Completed',
        'name': 'DownloadedEpisodesScan',
        'trigger': 'manual'
    },
    'priority': 'normal',
    'status': 'queued',
    'queued': '2020-08-17T00:45:53.4061066Z',
    'trigger': 'manual',
    'state': 'queued',
    'manual': True,
    'startedOn': '2020-08-17T00:45:53.4061066Z',
    'sendUpdatesToClient': False,
    'updateScheduledTask': True,
    'id': 11981
}
2020 - 08 - 16 19: 45: 53 - autoprocess.sonarr - INFO - [INFO] Sonarr response: queued.

I am going to blast the series again and rerun with Sonarr on trace to maybe get the ID in its output.

[mdhiggins]

Looks like the only different aside from the state/status is that the started one has a start time in addition to a queued time

    'queued': '2020-08-17T00:45:38.4272724Z',
    'started': '2020-08-17T00:45:38.4292662Z',

which would make sense

If you look in your logs for the jobs that happened just before the started one, does it by any chance have the same id? ('id': 11974)

The thing that makes this whole process confusing is that the normal states should go queued -> started -> completed so its not entirely unexpected that some what say started but then I'm not sure why it would fail

Also I did have one final question that I should have confirmed way in advance, but just wanted to confirm you don't have completed download handling enabled in sonarr correct? (sonarr > settings > download client)

[DamenQuixotic]

Correct I do not have CDH turned on per the readme here.

I will check on these new logs if the ID comes up in multiple spots.

[DamenQuixotic]

Okay so the ID this one did appear twice.

First appearance:

2020 - 08 - 16 20: 38: 41 - autoprocess.sonarr - DEBUG - {
    'name': 'DownloadedEpisodesScan',
    'body': {
        'sendUpdatesToClient': False,
        'sendUpdates': False,
        'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E04.WEB.h264-WALT',
        'importMode': 'auto',
        'updateScheduledTask': True,
        'completionMessage': 'Completed',
        'name': 'DownloadedEpisodesScan',
        'trigger': 'manual'
    },
    'priority': 'normal',
    'status': 'queued',
    'queued': '2020-08-17T01:38:41.3162771Z',
    'trigger': 'manual',
    'state': 'queued',
    'manual': True,
    'startedOn': '2020-08-17T01:38:41.3162771Z',
    'sendUpdatesToClient': False,
    'updateScheduledTask': True,
    'id': 12091
}
2020 - 08 - 16 20: 38: 41 - autoprocess.sonarr - INFO - [INFO] Sonarr response: queued.

Second appearance:

2020 - 08 - 16 20: 39: 02 - autoprocess.sonarr - DEBUG - {
    'name': 'DownloadedEpisodesScan',
    'body': {
        'sendUpdatesToClient': False,
        'sendUpdates': False,
        'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E04.WEB.h264-WALT',
        'importMode': 'auto',
        'updateScheduledTask': True,
        'completionMessage': 'Completed',
        'name': 'DownloadedEpisodesScan',
        'trigger': 'manual'
    },
    'priority': 'normal',
    'status': 'started',
    'queued': '2020-08-17T01:38:41.3162771Z',
    'started': '2020-08-17T01:38:49.0353403Z',
    'trigger': 'manual',
    'state': 'started',
    'manual': True,
    'startedOn': '2020-08-17T01:38:41.3162771Z',
    'stateChangeTime': '2020-08-17T01:38:49.0353403Z',
    'sendUpdatesToClient': False,
    'updateScheduledTask': True,
    'id': 12091
}
2020 - 08 - 16 20: 39: 02 - autoprocess.sonarr - INFO - [INFO] Sonarr response: started.

[mdhiggins]

Did 12091 fail? It looks like it queued both times (not started) and it looks like the same path ('path': 'C:\ProgramData\NZBGet\complete\Doug.S01E04.WEB.h264-WALT)

[DamenQuixotic]

Sorry I pasted in the same block twice on accident. I updated the comment just now.

[mdhiggins]

Alright so this does look interesting because it's the same path. It looks like the API is being called twice for some reason on the same path. Can you send the excerpt for this section of the log to me with a good chunk of the surrounding stuff. Leave everything in so I can see if its being trigger twice

[DamenQuixotic]

Sent you an email with the sma.log. It doesn't have a lot of bloat because I cleared it out before this last batch so if you search for the ID its all there for you. Let me know if I can send anything else helpful.

[DamenQuixotic]

Oh also this may be a valuable nugget, the file that did NOT get imported in that batch is not episode 4. its actually episode 10.

Which makes sense because the second call for that ID is right after it tried to do some episode 10 stuff. So it looks like that API call got highjacked and didn't actually import episode 10 and instead tried episode 4 again for some reason.

[DamenQuixotic]

[mdhiggins]

Yeah this is bizarre, the API request is for it to scan the episode 10 directory but instead the api responds saying its already trying to scan the episode 4 directory. Seems like this is a sonarr bug with the API call

The first call which works as expected

2020-08-16 20:38:41 - autoprocess.sonarr - INFO - [INFO] Requesting Sonarr to scan directory 'C:\ProgramData\NZBGet\complete\Doug.S01E04.WEB.h264-WALT'.
2020-08-16 20:38:41 - autoprocess.sonarr - DEBUG - {'name': 'DownloadedEpisodesScan', 'body': {'sendUpdatesToClient': False, 'sendUpdates': False, 'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E04.WEB.h264-WALT', 'importMode': 'auto', 'updateScheduledTask': True, 'completionMessage': 'Completed', 'name': 'DownloadedEpisodesScan', 'trigger': 'manual'}, 'priority': 'normal', 'status': 'queued', 'queued': '2020-08-17T01:38:41.3162771Z', 'trigger': 'manual', 'state': 'queued', 'manual': True, 'startedOn': '2020-08-17T01:38:41.3162771Z', 'sendUpdatesToClient': False, 'updateScheduledTask': True, 'id': 12091}

And then the second one that fails

2020-08-16 20:39:02 - autoprocess.sonarr - INFO - [INFO] Requesting Sonarr to scan directory 'C:\ProgramData\NZBGet\complete\Doug.S01E10.WEB.h264-WALT'.
2020-08-16 20:39:02 - autoprocess.sonarr - DEBUG - {'name': 'DownloadedEpisodesScan', 'body': {'sendUpdatesToClient': False, 'sendUpdates': False, 'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S01E04.WEB.h264-WALT', 'importMode': 'auto', 'updateScheduledTask': True, 'completionMessage': 'Completed', 'name': 'DownloadedEpisodesScan', 'trigger': 'manual'}, 'priority': 'normal', 'status': 'started', 'queued': '2020-08-17T01:38:41.3162771Z', 'started': '2020-08-17T01:38:49.0353403Z', 'trigger': 'manual', 'state': 'started', 'manual': True, 'startedOn': '2020-08-17T01:38:41.3162771Z', 'stateChangeTime': '2020-08-17T01:38:49.0353403Z', 'sendUpdatesToClient': False, 'updateScheduledTask': True, 'id': 12091}

Its like its ignoring the directory and responding incorrectly

[DamenQuixotic]

If it is taking a while to scan the directory could that cause any issues? No clue here just grasping at straws. This issue does seem to not appear as often when you do smaller download batches. I am not sure I have ever seen it when doing single requests.

[mdhiggins]

I'm guessing its a problem with Sonarr when its getting lots of requests quickly I'm gonna have to look through their source code to see. I could potentially develop a workaround though to check and make sure the directories match and then retry with a delay if they don't

[mdhiggins]

Did you find anything indicating a problem in the sonarr logs?

[DamenQuixotic]

Even with trace logging that ID doesn't appear anywhere in the logs sadly.

[mdhiggins]

import sys
import os
import logging
import time

def processEpisode(dirName, settings, nzbGet=False, logger=None):

    if nzbGet:
        errorprefix = "[ERROR] "
        infoprefix = "[INFO] "
    else:
        errorprefix = ""
        infoprefix = ""

    log = logger or logging.getLogger(__name__)

    log.info("%sSonarr notifier started." % infoprefix)

    # Import Requests
    try:
        import requests
    except ImportError:
        log.exception("%sPython module REQUESTS is required. Install with 'pip install requests' then try again." % errorprefix)
        log.error("%sPython executable path is %s" % (errorprefix, sys.executable))
        return False

    host = settings.Sonarr['host']
    port = settings.Sonarr['port']
    apikey = settings.Sonarr['apikey']

    if apikey == '':
        log.error("%sYour Sonarr API Key can not be blank. Update autoProcess.ini." % errorprefix)
        return False

    try:
        ssl = int(settings.Sonarr['ssl'])
    except:
        ssl = 0
    if ssl:
        protocol = "https://"
    else:
        protocol = "http://"

    webroot = settings.Sonarr['webroot']
    url = protocol + host + ":" + str(port) + webroot + "/api/command"
    payload = {'name': 'downloadedepisodesscan', 'path': dirName}
    headers = {'X-Api-Key': apikey}

    log.debug("Sonarr host: %s." % host)
    log.debug("Sonarr port: %s." % port)
    log.debug("Sonarr webroot: %s." % webroot)
    log.debug("Sonarr apikey: %s." % apikey)
    log.debug("Sonarr protocol: %s." % protocol)
    log.debug("URL '%s' with payload '%s.'" % (url, payload))

    log.info("%sRequesting Sonarr to scan directory '%s'." % (infoprefix, dirName))
    return accessAPI(url, payload, headers, log)

def accessAPI(url, payload, headers, log, sleep=10, retry=0, maxretry=3):
    try:
        r = requests.post(url, json=payload, headers=headers)
        rstate = r.json()
        log.debug(rstate)
        log.info("%sSonarr response: %s." % (infoprefix, rstate['state']))
        if rstate['body']['path'] != payload['path']:
            if retry > maxretry:
                log.error("Sonarr returned path %s that does not match the directory that was requested to be scanned %s. Maximum number of retries exceeded (%d)." % (rstate['body']['path'], payload['path'], maxretry))
                return False
            log.error("Sonarr returned path %s that does not match the directory that was requested to be scanned %s. Trying again in %d seconds." % (rstate['body']['path'], payload['path'], sleep))
            time.sleep(sleep)
            return accessAPI(url, payload, headers, log, retry=(retry + 1))
        return True
    except:
        log.exception("%sUpdate to Sonarr failed, check if Sonarr is running, autoProcess.ini settings and make sure your Sonarr settings are correct (apikey?), or check install of python modules requests." % errorprefix)
        return False

Try replacing your sonarr.py file in the autoprocess folder with that modification and see if it is able to catch and overcome the problem

What that change should do is check if the directory you asked Sonarr to scan matches the directory that Sonarr returns, if they don't match, it waits 10 seconds and tries again with a max retry amount of 3

[DamenQuixotic]

The script just keeps failing now.

When you are trying to path match is it possible that one has double slashes and one does not causing it to always not match?

E.g.

2020-08-16 22:26:16 - autoprocess.sonarr - DEBUG - URL 'http://localhost:8989/api/command' with payload '{'name': 'downloadedepisodesscan', 'path': 'C:\\ProgramData\\NZBGet\\complete\\Doug.S02E01.Doug.Takes.the.Case-Dougs.Secret.Song.480p.WEB-DL.AAC2.0.H.264-SA89-xpost'}.'
2020-08-16 22:26:16 - autoprocess.sonarr - INFO - [INFO] Requesting Sonarr to scan directory 'C:\ProgramData\NZBGet\complete\Doug.S02E01.Doug.Takes.the.Case-Dougs.Secret.Song.480p.WEB-DL.AAC2.0.H.264-SA89-xpost'.

[DamenQuixotic]

The last line I get on each try is the info call right before you call accessAPI();

log.info("%sRequesting Sonarr to scan directory '%s'." % (infoprefix, dirName))

I do not get the debug log inside that function or the info trying to log the response.

[DamenQuixotic]

Ah nevermind. I don't know any python, but I was able to get the call working by moving the "requests" import inside your new function as it was declared up in the original function only.

I will probably let you figure out if that impacts anything else but for now I just copied:

try:
        import requests
    except ImportError:
        log.exception("%sPython module REQUESTS is required. Install with 'pip install requests' then try again." % errorprefix)
        log.error("%sPython executable path is %s" % (errorprefix, sys.executable))
        return False

inside your accessApi function.

[mdhiggins]

Yeah that's my bad, forgot to pass requests

import sys
import os
import logging
import time

def processEpisode(dirName, settings, nzbGet=False, logger=None):

    if nzbGet:
        errorprefix = "[ERROR] "
        infoprefix = "[INFO] "
    else:
        errorprefix = ""
        infoprefix = ""

    log = logger or logging.getLogger(__name__)

    log.info("%sSonarr notifier started." % infoprefix)

    # Import Requests
    try:
        import requests
    except ImportError:
        log.exception("%sPython module REQUESTS is required. Install with 'pip install requests' then try again." % errorprefix)
        log.error("%sPython executable path is %s" % (errorprefix, sys.executable))
        return False

    host = settings.Sonarr['host']
    port = settings.Sonarr['port']
    apikey = settings.Sonarr['apikey']

    if apikey == '':
        log.error("%sYour Sonarr API Key can not be blank. Update autoProcess.ini." % errorprefix)
        return False

    try:
        ssl = int(settings.Sonarr['ssl'])
    except:
        ssl = 0
    if ssl:
        protocol = "https://"
    else:
        protocol = "http://"

    webroot = settings.Sonarr['webroot']
    url = protocol + host + ":" + str(port) + webroot + "/api/command"
    payload = {'name': 'downloadedepisodesscan', 'path': dirName}
    headers = {'X-Api-Key': apikey}

    log.debug("Sonarr host: %s." % host)
    log.debug("Sonarr port: %s." % port)
    log.debug("Sonarr webroot: %s." % webroot)
    log.debug("Sonarr apikey: %s." % apikey)
    log.debug("Sonarr protocol: %s." % protocol)
    log.debug("URL '%s' with payload '%s.'" % (url, payload))

    log.info("%sRequesting Sonarr to scan directory '%s'." % (infoprefix, dirName))
    return accessAPI(url, payload, headers, log, requests)

def accessAPI(url, payload, headers, log, requests, sleep=10, retry=0, maxretry=3):
    try:
        r = requests.post(url, json=payload, headers=headers)
        rstate = r.json()
        log.debug(rstate)
        log.info("%sSonarr response: %s." % (infoprefix, rstate['state']))
        if rstate['body']['path'] != payload['path']:
            if retry > maxretry:
                log.error("Sonarr returned path %s that does not match the directory that was requested to be scanned %s. Maximum number of retries exceeded (%d)." % (rstate['body']['path'], payload['path'], maxretry))
                return False
            log.error("Sonarr returned path %s that does not match the directory that was requested to be scanned %s. Trying again in %d seconds." % (rstate['body']['path'], payload['path'], sleep))
            time.sleep(sleep)
            return accessAPI(url, payload, headers, log, requests, retry=(retry + 1))
        return True
    except:
        log.exception("%sUpdate to Sonarr failed, check if Sonarr is running, autoProcess.ini settings and make sure your Sonarr settings are correct (apikey?), or check install of python modules requests." % errorprefix)
        return False

That should fix that error. Your fix should also have worked to fix it as well, so let me know if it solves the original problem

[DamenQuixotic]

Jobs are getting flagged as post processing failed in NZBGet now for some reason.

Mon Aug 17 2020 09:08:37 | Post-process-script NZBGetPostProcess.py for The.Batman.S01E01.iNTERNAL.DVDRip.XviD-RUNNER failed (terminated with unknown status)

I didn't see anything particularly wrong in the sma.log though.

I guess for now I am just going to call it for trying to integrate this tool, I am positive the problem doesn't really have anything to do with your code but more on Sonarr's side. The main reason for using your tool was to just try and get all the codecs into a spot where direct play is most likely to happen but I value consistency of adding over that I suppose.

I might come back and try to figure this out at some point and if I do I will probably reach out again if that's okay.

[mdhiggins]

This seems like a solvable problem and I think we're at the finish line just a few tweaks and it should be fixed. Getting the sonarr people to acknowledge this is a real issue and address it is probably a long shot so this is your best bet.

I wonder if there's a small syntax problem that's causing your new error. Anything in sma.log about why nzbgetpostprocess didn't work?

Don't give up quite yet cause I think the solution I put together should solve this

[mdhiggins]

60c4290f3b53840042517c4c5212e3d45ce9175b

Pushed the changes to the master branch to hopefully make things a little easier to test

@morpheus2n2 if you could try this update and see if it fixes your situation as well that would be appreciated

When it catches sonarr making a mistake you should get this error message:

Sonarr returned path %s that does not match the directory that was requested to be scanned %s. Trying again in %d seconds.

and it should hopefully retry and recover so keep an eye out for that

[morpheus2n2]

NP will do, not had it since upgrading PC however never say never as the say goes

[mdhiggins]

Seems like situations where you process a ton of files at once causes sonarr to mess up, so batch processing a season that requires minimal to no conversion is probably your best bet to recreate the issue as that will hammer the API with lots of requests in rapid succession.

At the very least it would be good to check and make sure I didn't break anything with usual operations 😂