Post processing fails on second file

[ShivALLmyTinders]

Hi, I am having issues with failed post-processing of NZB files after an initial successfully processed file. Basically NzbToMedia is successfully processing one file at its first use after installation, and then failing every subsequent file.

If I delete the NzbToMedia folder and conduct a fresh git clone via SSH the first attempt to post-process a file succeeds, however each subsequent attempt fails. This is a repeatable fault (ie delete, re-clone, re-post-process a file successfully, failed post-process of other files). I can't work out whether there is some tail end modification of the config file occurring or something which might be affecting each subsequent attempt.

Log of the failed attempt and subsequent successful attempts below.

Technical Specs

1. Running on QNAP QTS version 4.5.3
2. Python version 3.8.3
3. Download Client NZBget
4. Intended Media Management Radarr and Sonarr

Logs

Failed log:

INFO 2021-05-24 20:01:44 Queueing The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP for post-processing INFO 2021-05-24 20:01:48 Cleaning up The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO 2021-05-24 20:01:48 Nothing to cleanup for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO 2021-05-24 20:01:48 Executing post-process-script nzbToMedia/nzbToMedia.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO 2021-05-24 20:01:53 nzbToMedia: [20:01:53] [ERROR]::MAIN: Error Parsing failed with 12 errors. INFO 2021-05-24 20:01:53 nzbToMedia: Cannot compute the section depth at line 84. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 85. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 86. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 87. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 88. INFO 2021-05-24 20:01:53 nzbToMedia: 7 more error(s)! when copying to .cfg INFO 2021-05-24 20:01:53 nzbToMedia: [20:01:53] [ERROR]::MAIN: Unable to migrate config file /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/autoProcessMedia.cfg, exiting ... INFO 2021-05-24 20:01:53 nzbToMedia: Changing to directory: /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia INFO 2021-05-24 20:01:53 nzbToMedia: -- Cleaning bytecode -- INFO 2021-05-24 20:01:53 nzbToMedia: WARNING: Automatic cleanup could not be executed. INFO 2021-05-24 20:01:53 nzbToMedia: If errors occur, manual cleanup may be required. INFO 2021-05-24 20:01:53 nzbToMedia: REASON : Error: [Errno 2] No such file or directory: 'git' INFO 2021-05-24 20:01:53 nzbToMedia: -- Cleaning folders: ['libs', 'core'] -- INFO 2021-05-24 20:01:53 nzbToMedia: WARNING: Automatic cleanup could not be executed. INFO 2021-05-24 20:01:53 nzbToMedia: If errors occur, manual cleanup may be required. INFO 2021-05-24 20:01:53 nzbToMedia: REASON : Error: [Errno 2] No such file or directory: 'git' INFO 2021-05-24 20:01:53 nzbToMedia: Returning to directory: / INFO 2021-05-24 20:01:53 nzbToMedia: -- Cleanup finished -- INFO 2021-05-24 20:01:53 nzbToMedia: Traceback (most recent call last): INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/nzbToMedia.py", line 1061, in INFO 2021-05-24 20:01:53 nzbToMedia: exit(main(sys.argv)) INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/nzbToMedia.py", line 885, in main INFO 2021-05-24 20:01:53 nzbToMedia: core.initialize(section) INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/core/init.py", line 1024, in initialize INFO 2021-05-24 20:01:53 nzbToMedia: configure_migration() INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/core/init.py", line 348, in configure_migration INFO 2021-05-24 20:01:53 nzbToMedia: CFG = config.addnzbget() INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/core/configuration.py", line 264, in addnzbget INFO 2021-05-24 20:01:53 nzbToMedia: cfg_new = config() INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/core/configuration.py", line 102, in init INFO 2021-05-24 20:01:53 nzbToMedia: super(configobj.ConfigObj, self).init(*args, **kw) INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/libs/common/configobj/init.py", line 1205, in init INFO 2021-05-24 20:01:53 nzbToMedia: self._load(infile, configspec) INFO 2021-05-24 20:01:53 nzbToMedia: File "/share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/libs/common/configobj/init.py", line 1302, in _load INFO 2021-05-24 20:01:53 nzbToMedia: raise error INFO 2021-05-24 20:01:53 nzbToMedia: configobj.ConfigObjError: Parsing failed with 12 errors. INFO 2021-05-24 20:01:53 nzbToMedia: Cannot compute the section depth at line 84. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 85. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 86. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 87. INFO 2021-05-24 20:01:53 nzbToMedia: Duplicate keyword name at line 88. INFO 2021-05-24 20:01:53 nzbToMedia: 7 more error(s)! ERROR 2021-05-24 20:01:53 Post-process-script nzbToMedia/nzbToMedia.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP failed (terminated with unknown status) INFO 2021-05-24 20:01:53 Executing post-process-script Logger.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP

Successful log:

INFO Mon May 24 2021 20:15:53 Unpausing download after post-processing INFO Mon May 24 2021 20:15:53 Collection The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP added to history INFO Mon May 24 2021 20:15:53 Post-process-script Logger.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP skipped INFO Mon May 24 2021 20:15:53 Logger: Destination directory doesn't exist, exiting INFO Mon May 24 2021 20:15:53 Executing post-process-script Logger.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:15:53 Post-process-script nzbToMedia/nzbToMedia.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP successful INFO Mon May 24 2021 20:15:52 nzbToMedia: NzbDrone: Successfully post-processed The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP! INFO Mon May 24 2021 20:15:52 nzbToMedia: -- Cleanup finished -- INFO Mon May 24 2021 20:15:52 nzbToMedia: Returning to directory: / INFO Mon May 24 2021 20:15:52 nzbToMedia: REASON : Error: [Errno 2] No such file or directory: 'git' INFO Mon May 24 2021 20:15:52 nzbToMedia: If errors occur, manual cleanup may be required. INFO Mon May 24 2021 20:15:52 nzbToMedia: WARNING: Automatic cleanup could not be executed. INFO Mon May 24 2021 20:15:52 nzbToMedia: -- Cleaning folders: ['libs', 'core'] -- INFO Mon May 24 2021 20:15:52 nzbToMedia: REASON : Error: [Errno 2] No such file or directory: 'git' INFO Mon May 24 2021 20:15:52 nzbToMedia: If errors occur, manual cleanup may be required. INFO Mon May 24 2021 20:15:52 nzbToMedia: WARNING: Automatic cleanup could not be executed. INFO Mon May 24 2021 20:15:52 nzbToMedia: -- Cleaning bytecode -- INFO Mon May 24 2021 20:15:52 nzbToMedia: Changing to directory: /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia INFO Mon May 24 2021 20:15:52 nzbToMedia: [20:15:52] [INFO]::MAIN: The /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/nzbToMedia.py script completed successfully. INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [POSTPROCESS]::NZBDRONE: SUCCESS: The download succeeded, sending a post-process request INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [INFO]::MAIN: FLATTEN: Flattening directory: /share/CACHEDEV1_DATA/Download/nzbget/downloads/completed/The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [INFO]::MAIN: NzbDrone:TV fork set to default INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [INFO]::MAIN: Attempting to verify TV fork INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [INFO]::MAIN: Calling NzbDrone:TV to post-process:The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:14:50 nzbToMedia: [20:14:50] [INFO]::MAIN: Auto-detected SECTION:NzbDrone INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: Script triggered from NZBGet Version 21.1-testing-r2311. INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: ######################################################### INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: ## ..::[nzbToMedia.py]::.. ## INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: ######################################################### INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [WARNING]::MAIN: Install ffmpeg with x264 support to enable this feature ... INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [WARNING]::MAIN: Failed to locate ffprobe. Video corruption detection disabled! INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: nzbToMedia Version:12.1.08 Branch:master (Linux 4.14.24-qnap) INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: No update needed INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [ERROR]::MAIN: Unable to determine installed version via git, please check your logs! INFO Mon May 24 2021 20:14:49 nzbToMedia: [20:14:49] [INFO]::MAIN: Checking if git needs an update INFO Mon May 24 2021 20:14:48 nzbToMedia: [20:14:48] [INFO]::MAIN: Database upgrade required: Initial Schema INFO Mon May 24 2021 20:14:48 nzbToMedia: [20:14:48] [INFO]::MAIN: Checking database structure... INFO Mon May 24 2021 20:14:48 nzbToMedia: [20:14:48] [INFO]::MAIN: Python v3.8 will reach end of life in 1239 days. INFO Mon May 24 2021 20:14:43 Executing post-process-script nzbToMedia/nzbToMedia.py for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:14:42 Nothing to cleanup for The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:14:42 Cleaning up The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP INFO Mon May 24 2021 20:14:42 Pausing download before post-processing INFO Mon May 24 2021 20:14:40 Queueing The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP for post-processing INFO Mon May 24 2021 20:14:40 The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP returned from history back to download queue INFO Mon May 24 2021 20:14:40 Post-processing again The.Handmaids.Tale.S04E05.720p.WEB.H264-GGWP

[clinton-hall]

are you manually editing /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/autoProcessMedia.cfg or just letting NZBGet set all of the configurations?

to test, just try deleting this file /share/CACHEDEV1_DATA/Download/nzbget/scripts/nzbToMedia/autoProcessMedia.cfg and not having to re-clone etc.

I'm not sure exactly what is going on here, I can't tell if the issue is with the .cfg or if something is being sent wrong from NZBGet...

[clinton-hall]

As a note. I have just upgraded to nzbget 21.1-testing-r2311 I was previously on 21.0 and had no issues. Hopefully a download will occur soon so that I can verify functionality and rule out any issues with the way nzbget sends the config.

[ShivALLmyTinders]

Hi mate, Thanks for looking at this. I tried deleting the autoprocessmedia file and post-processing but the same behaviour occurs ie one successful file followed by a fail. However, the autoprocessmedia file reappears after the first successful file along with a duplicate called autoprocessmedia.cfg.old - I'm not sure how this is occurring, whether it's Nzbget or something else. As far as I'm aware I have nothing else set up to edit the config file.

Cheers

On Wed, 26 May 2021, 19:45 Clinton Hall, @.***> wrote:

As a note. I have just upgraded to nzbget 21.1-testing-r2311 I was previously on 21.0 and had no issues. Hopefully a download will occur soon so that I can verify functionality and rule out any issues with the way nzbget sends the config.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/clinton-hall/nzbToMedia/issues/1829#issuecomment-848629076, or unsubscribe https://github.com/notifications/unsubscribe-auth/AQMWFMZ555NYMJIIHLMEZ2DTPS7KFANCNFSM45M6XAKA .

[RomainBoulay]

I can second what @ShivALLmyTinders describes, I have the same problem. I'm using nzbget version 21 and nzbToMedia at tag 12.1.08 (this commit: 9d64c2f47869584ebf3ca269632e1f03a461f99e).

I noticed these error logs:

These are the lines of the config file:

I have tried to manually edit the cfg file and I removed the automatically added [[""]] objects (there are more occurrences than the one shown in the screenshot above), which works: the next post-process succeeds. However, these [[""]] objects re-appear just after the run, causing the next post-processes to fail again.

(Ho and if that helps, I'm also not using Radarr)

[clinton-hall]

ok. this does make sense.

The process is that on each run, the .cfg file is copied over to .cfg.old and then then contents are read in to .cfg and finally the configuration specified in NZBGet is applied.

so creating the .cfg and cfg.old is normal and expected.

what is wrong is that an invalid (blank) category "" is being created.

in NZBGet what script are you calling? nzbToMedia.py or nzbToSickBeard.py? if nzbToMedia.py please check all of the parameters in NZBGet - Settings - NZBTOMEDIA make sure that each "Category" has a unique name

e.g. cpsCategory = movies raCategory = movies2 if any of these are blank that could cause an issue.

The other option is to set each category in NZBGet to call only the specific script you want. e.g. Category TV calls nzbToNzbDrone then you set all the required parameters (host, port, apikey etc) in NZBget - Settings - NZBTONZBDRONE

[RomainBoulay]

Thanks @clinton-hall for looking into this!

So I applied your advice (I'm using nzbToMedia) and that's how the config file looks after my edits (this is the output of the command cat autoProcessMedia.cfg | grep "\["):

[General]
[Posix]
[Windows]
[CouchPotato]
    [[movie]]
[Radarr]
    [[raMovie]]
[Watcher3]
    [[waMovie]]
[SickBeard]
    [[tv]]
[NzbDrone]
    [[nbTV]]
    [[tv2]]
[HeadPhones]
    [[hpMusic]]
[Lidarr]
    [[liMusic]]
[Mylar]
    [[comics]]
[Gamez]
    [[games]]
[LazyLibrarian]
    [[books]]
[Network]
[Nzb]
[Torrent]
[Extensions]
[Plex]
[Transcoder]
[WakeOnLan]
[UserScript]
    [[UNCAT]]
    [[mine]]
[ASCII]
[Passwords]
[Custom]

As you can see, all the categories are unique.

So I did reboot nzbget and I post-processed a previously failed file. It worked. However, when I grep again the config file, I get this:

[General]
[Posix]
[Windows]
[CouchPotato]
    [[movie]]
[Radarr]
    [[movie]]
    [[raMovie]]
    [[raMovies]]
[Watcher3]
    [[movie]]
    [[waMovie]]
    [[w3Movies]]
[SickBeard]
    [[tv]]
[NzbDrone]
    [[tv]]
    [[nbTV]]
    [[tv2]]
    [[ndTV]]
[HeadPhones]
    [[music]]
    [[hpMusic]]
[Lidarr]
    [[music]]
    [[liMusic]]
    [[music2]]
[Mylar]
    [[comics]]
[Gamez]
    [[games]]
[LazyLibrarian]
    [[books]]
[Network]
[Nzb]
[Torrent]
[Extensions]
[Plex]
[Transcoder]
[WakeOnLan]
[UserScript]
    [[UNCAT]]
    [[mine]]
[ASCII]
[Passwords]
[Custom]

It's unexpected to me, as I did not manually re-edit the config file nor changed any settings via nzbget. I don't have another file to post-process, but I am under the impression that my next post-process will fail again (given the categories aren't unique anymore).

@clinton-hall do you know what could cause this issue?

Anyways, thanks again for your help, and big thanks for all the work you've done on this repository!

[ShivALLmyTinders]

Ok so I had an unlabelled category for the CouchPotato settings in the NzbToMedia config under extension scripts - all the categories in the main NZBGet settings were filled already. Although CouchPotato wasn't being called (was using Sonarr) this seems to have been the issue with subsequent processing. I've only tried one file and will update again if the problem re-appears, but everything seems to be working as intended at the moment...

[clinton-hall]

@RomainBoulay Can you check nzbget - settings - NZBTO* Look at all of the script configurations and look at the categories.

Also, look at the scripts that are executed for each category. Is it possible that you are executing nzbToMedia and then executing nzbToNzbDrone or some other similar scenario?

If this is not apparent, try taking a look at the nzbget config and see if: movie raMovies w3Movies tv ndTV music Appear in the config?

[RomainBoulay]

This is the grep on the nzbget config file:

➜  nzbget cat var/nzbget.conf | grep nzbToMedia/ | grep Cat
Category1.Extensions=GetScripts/flatten.py, GetScripts/DeleteSamples.py, nzbToMedia/nzbToMedia.py, Pushover.py, Pushover-queue.py
Category2.Extensions=GetScripts/flatten.py, GetScripts/DeleteSamples.py, nzbToMedia/nzbToMedia.py, Pushover.py, Pushover-queue.py
nzbToMedia/nzbToCouchPotato.py:cpsCategory=movie
nzbToMedia/nzbToGamez.py:gzCategory=games
nzbToMedia/nzbToHeadPhones.py:hpCategory=music
nzbToMedia/nzbToMedia.py:cpsCategory=movie
nzbToMedia/nzbToMedia.py:raCategory=raMovies
nzbToMedia/nzbToMedia.py:sbCategory=tv
nzbToMedia/nzbToMedia.py:ndCategory=ndTV
nzbToMedia/nzbToMedia.py:hpCategory=music
nzbToMedia/nzbToMedia.py:myCategory=comics
nzbToMedia/nzbToMedia.py:gzCategory=games
nzbToMedia/nzbToMedia.py:usCategory=mine
nzbToMedia/nzbToMylar.py:myCategory=comics
nzbToMedia/nzbToNzbDrone.py:ndCategory=tv2
nzbToMedia/nzbToRadarr.py:raCategory=movies2
nzbToMedia/nzbToSickBeard.py:sbCategory=tv
nzbToMedia/nzbToMedia.py:W3Category=w3Movies
nzbToMedia/nzbToMedia.py:liCategory=music2
nzbToMedia/nzbToMedia.py:llCategory=books
nzbToMedia/nzbToLazyLibrarian.py:llCategory=books
nzbToMedia/nzbToLidarr.py:liCategory=music2
nzbToMedia/nzbToWatcher3.py:W3Category=moviewatcher3

Also, look at the scripts that are executed for each category. Is it possible that you are executing nzbToMedia and then executing nzbToNzbDrone or some other similar scenario?

No I checked, and I only call nzbToMedia/nzbToMedia.py.

I have no idea what causes my bug, @clinton-hall I would appreciate your help to troubleshoot 🙏🏻

[clinton-hall]

What categories are defined in NZBGet and which categories are set to call nzbToMedia.py

Having duplicate categories isn't an issue if the duplicates are not enabled. It should only cause issues if you have the same (sub)category in more than one primary category, with Enabled = 1.

Just checking you haven't edited the autoProcessMedia.cfg.spec file at all?

[RomainBoulay]

What categories are defined in NZBGet and which categories are set to call nzbToMedia.py

I have 2 categories that use extensions:

Category1.Extensions=GetScripts/flatten.py, GetScripts/DeleteSamples.py, nzbToMedia/nzbToMedia.py, Pushover.py, Pushover-queue.py
Category2.Extensions=GetScripts/flatten.py, GetScripts/DeleteSamples.py, nzbToMedia/nzbToMedia.py, Pushover.py, Pushover-queue.py

Category1 is movie. Category2 is tv.

I have 2 other categories (software and music), but they don't use any extensions.

---

Just checking you haven't edited the autoProcessMedia.cfg.spec file at all?

No, it doesn't seem so:

➜  nzbToMedia git:(master) git rev-parse HEAD
9d64c2f47869584ebf3ca269632e1f03a461f99e
➜  nzbToMedia git:(master) git status        
On branch master
Your branch is up to date with 'origin/master'.

nothing to commit, working tree clean

---

Having duplicate categories isn't an issue if the duplicates are not enabled. It should only cause issues if you have the same (sub)category in more than one primary category, with Enabled = 1.

I guess you're referring to the nzbToMedia categories? Should I then make sure that all the unused categories present in the autoProcessMedia.cfg file are all set to 0?

Side question, as I don't see any 'enable' options in nzbget > Settings > nzbToMedia, how are the enable flags determined?

[clinton-hall]

Yes, set un-used categories to Enabled = 0

The enable flags are set when the category is defined in the cfg and the script is called for that category.

i.e. if you are downloading a Category "movie" and you have in your NZBGet config "nzbToMedia/nzbToMedia.py:cpsCategory=movie" Then in the autoProcessMedia.cfg

[CouchPotato]
    [[movie]]
        enable = 1

will be set.

Just to confirm here. Are you using CouchPotato, or another media management tool?

[RomainBoulay]

I un-set these categories, and after a quick try, it seems to work again. I'm not sure what caused this bug, but in any case, thanks for your help @clinton-hall!