nzbToMedia Postprocessing Fail with NZBGet, Couchpotato, and nzbToCouchPotato

Getting a post processing failure with NZBGet and Couchpotato, using the nzbtocouchpotato script. Seems the script is not honoring my 'wait_for' time. My wait for time is set to 15 minutes for couchpotato.

Technical Specs

Running on: Unraid 6.7.2 Docker
Python version: 2.7
Download Client: NZBget
Intended Media Management: CouchPotoato

Expected behavior Script should honor wait_for time and process successfully

Log

Couchpotato:

09-12 22:33:53 INFO
[o.core.downloaders.nzbget] Sending "What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev" to NZBGet.
09-12 22:33:54 INFO
[o.core.downloaders.nzbget] NZB sent successfully to NZBGet
09-12 22:33:55 INFO
[tato.core.plugins.release] Snatched "What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev": What Men Want (2019) in 720p from Newznab, hydra
09-12 22:33:55 INFO
[core.media.movie.searcher] Found 3 releases for "What Men Want" before ETA. Select and download via the dashboard.
09-12 22:36:42 INFO
[tato.core.plugins.renamer] Scanning media folder /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)...
09-12 22:36:42 INFO
[tato.core.plugins.scanner] Found 1 movies in the folder /downloads/completed/Movies
09-12 22:36:42 INFO
[hpotato.core.plugins.base] Opening url: get https://api.themoviedb.org/3/movie/tt7634968?api_key=xxx&append_to_response=alternative_titles&language=en, data: []
09-12 22:36:42 INFO
[hpotato.core.plugins.base] Opening url: get https://api.couchpota.to/info/tt7634968/?ignore=1, data: []
09-12 22:36:42 INFO
[hpotato.core.plugins.base] Opening url: get https://www.omdbapi.com/?apikey=xxx&type=movie&i=tt7634968, data: []
09-12 22:36:42 INFO
[ie.providers.info.omdbapi] Found: What Men Want (2019)
09-12 22:36:42 INFO
[tato.core.plugins.renamer] Moving "/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv" to "/movies/What Men Want (2019)/What Men Want.mkv"

nzbtomedia.log:

2019-09-12 23:01:16 INFO    ::MAIN: Python v2.7 will reach end of life in 111 days.
2019-09-12 23:01:16 WARNING ::MAIN: Please upgrade to a more recent Python version.
2019-09-12 23:01:16 INFO    ::MAIN: Checking database structure...
2019-09-12 23:01:16 DEBUG   ::MAIN: Checking Initial Schema database upgrade
2019-09-12 23:01:16 DB      ::MAIN: nzbtomedia.db: SELECT 1 FROM sqlite_master WHERE name = ?; with args (u'db_version',)
2019-09-12 23:01:16 DB      ::MAIN: nzbtomedia.db: SELECT db_version FROM db_version
2019-09-12 23:01:16 DEBUG   ::MAIN: InitialSchema upgrade not required
2019-09-12 23:01:16 INFO    ::MAIN: Checking if source needs an update
2019-09-12 23:01:17 DEBUG   ::MAIN: cur_commit = None % (newest_commit)= 46b2e8998ce7c0e4b853272f0bdb06a558852c81, num_commits_behind = 0
2019-09-12 23:01:17 ERROR   ::MAIN: Unknown current version number, don't know if we should update or not
2019-09-12 23:01:17 INFO    ::MAIN: nzbToMedia Version:12.1.01 Branch:master (Linux 4.19.56-Unraid)
2019-09-12 23:01:17 WARNING ::MAIN: Failed to locate par2. Repair and rename using par files will not be possible!
2019-09-12 23:01:17 WARNING ::MAIN: Failed to locate ffmpeg. Transcoding disabled!
2019-09-12 23:01:17 WARNING ::MAIN: Install ffmpeg with x264 support to enable this feature  ...
2019-09-12 23:01:17 INFO    ::MAIN: #########################################################
2019-09-12 23:01:17 INFO    ::MAIN: ## ..::[nzbToMedia.pyc]::.. ##
2019-09-12 23:01:17 INFO    ::MAIN: #########################################################
2019-09-12 23:01:17 DEBUG   ::MAIN: Options passed into nzbToMedia: ['/scripts/nzbToMedia/nzbToCouchPotato.py']
2019-09-12 23:01:17 INFO    ::MAIN: Script triggered from NZBGet Version 21.0.
2019-09-12 23:01:17 DEBUG   ::MAIN: Adding NZB download info for directory /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968) to database
2019-09-12 23:01:17 DB      ::MAIN: nzbtomedia.db: UPDATE downloads SET status = ?, client_agent = ?, last_update = ?, input_id = ?, input_hash = ?, input_name = ? WHERE input_directory = ? with args [0, u'nzbget', 737314, u'cecd85738c589d66fe16a117f8b0e9fd', u'cecd85738c589d66fe16a117f8b0e9fd', u'What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)', u'/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)']
2019-09-12 23:01:17 DB      ::MAIN: nzbtomedia.db: INSERT OR IGNORE INTO downloads (status, client_agent, last_update, input_id, input_hash, input_name) VALUES (?, ?, ?, ?, ?, ?) with args [0, u'nzbget', 737314, u'cecd85738c589d66fe16a117f8b0e9fd', u'cecd85738c589d66fe16a117f8b0e9fd', u'What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)']
2019-09-12 23:01:17 INFO    ::MAIN: Auto-detected SECTION:CouchPotato
2019-09-12 23:01:17 INFO    ::MAIN: Calling CouchPotato:Movies to post-process:What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
2019-09-12 23:01:17 INFO    ::MAIN: Attemping imdbID lookup for What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
2019-09-12 23:01:17 INFO    ::MAIN: Searching folder and file names for imdbID ...
2019-09-12 23:01:17 INFO    ::MAIN: Found imdbID [tt7634968]
2019-09-12 23:01:17 DEBUG   ::SERVER: Attempting to connect to server at https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/
2019-09-12 23:01:18 DEBUG   ::SERVER: Server responded at https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/
2019-09-12 23:01:18 DEBUG   ::MAIN: Opening URL: https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/media.get with PARAMS: {u'id': 'tt7634968'}
2019-09-12 23:01:18 DEBUG   ::EXCEPTION: Replacing file name 63d178d8d2b94892a28c8e1ada3cfeeb with directory name What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
2019-09-12 23:01:18 DEBUG   ::EXCEPTION: Replacing file name /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/63d178d8d2b94892a28c8e1ada3cfeeb.mkv with download name /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv
2019-09-12 23:01:18 INFO    ::SUBTITLES: Attempting to download subtitles for /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv
2019-09-12 23:02:29 DEBUG   ::COUCHPOTATO: Opening URL: https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/renamer.scan with PARAMS: {u'downloader': u'NZBGet', u'download_id': u'cecd85738c589d66fe16a117f8b0e9fd', u'media_folder': '/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)'}
2019-09-12 23:02:29 POSTPROCESS::COUCHPOTATO: Starting renamer scan for What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)

NZBGet:

Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: /scripts/nzbToMedia/eol.py:146: LifetimeWarning: Python 2.7 is no longer supported.
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato:   warnings.warn(msg, LifetimeWarning)
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [INFO]::MAIN: Python v2.7 will reach end of life in 111 days.
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [WARNING]::MAIN: Please upgrade to a more recent Python version.
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [INFO]::MAIN: Checking database structure...
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [DEBUG]::MAIN: Checking Initial Schema database upgrade
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [DB]::MAIN: nzbtomedia.db: SELECT 1 FROM sqlite_master WHERE name = ?; with args (u'db_version',)
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [DB]::MAIN: nzbtomedia.db: SELECT db_version FROM db_version
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [DEBUG]::MAIN: InitialSchema upgrade not required
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:16] [INFO]::MAIN: Checking if source needs an update
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DEBUG]::MAIN: cur_commit = None % (newest_commit)= 46b2e8998ce7c0e4b853272f0bdb06a558852c81, num_commits_behind = 0
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [ERROR]::MAIN: Unknown current version number, don't know if we should update or not
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: nzbToMedia Version:12.1.01 Branch:master (Linux 4.19.56-Unraid)
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [WARNING]::MAIN: Failed to locate par2. Repair and rename using par files will not be possible!
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [WARNING]::MAIN: Failed to locate ffmpeg. Transcoding disabled!
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [WARNING]::MAIN: Install ffmpeg with x264 support to enable this feature  ...
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: #########################################################
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: ## ..::[nzbToMedia.pyc]::.. ##
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: #########################################################
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DEBUG]::MAIN: Options passed into nzbToMedia: ['/scripts/nzbToMedia/nzbToCouchPotato.py']
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Script triggered from NZBGet Version 21.0.
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DEBUG]::MAIN: Adding NZB download info for directory /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968) to database
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DB]::MAIN: nzbtomedia.db: UPDATE downloads SET status = ?, client_agent = ?, last_update = ?, input_id = ?, input_hash = ?, input_name = ? WHERE input_directory = ? with args [0, u'nzbget', 737314, u'cecd85738c589d66fe16a117f8b0e9fd', u'cecd85738c589d66fe16a117f8b0e9fd', u'What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)', u'/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)']
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DB]::MAIN: nzbtomedia.db: INSERT OR IGNORE INTO downloads (status, client_agent, last_update, input_id, input_hash, input_name) VALUES (?, ?, ?, ?, ?, ?) with args [0, u'nzbget', 737314, u'cecd85738c589d66fe16a117f8b0e9fd', u'cecd85738c589d66fe16a117f8b0e9fd', u'What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)']
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Auto-detected SECTION:CouchPotato
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Calling CouchPotato:Movies to post-process:What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Attemping imdbID lookup for What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Searching folder and file names for imdbID ...
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [INFO]::MAIN: Found imdbID [tt7634968]
Thu Sep 12 23:01:17 2019	INFO	nzbToCouchPotato: [23:01:17] [DEBUG]::SERVER: Attempting to connect to server at https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/
Thu Sep 12 23:01:18 2019	INFO	nzbToCouchPotato: [23:01:18] [DEBUG]::SERVER: Server responded at https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/
Thu Sep 12 23:01:18 2019	INFO	nzbToCouchPotato: [23:01:18] [DEBUG]::MAIN: Opening URL: https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/media.get with PARAMS: {u'id': 'tt7634968'}
Thu Sep 12 23:01:18 2019	INFO	nzbToCouchPotato: [23:01:18] [DEBUG]::EXCEPTION: Replacing file name 63d178d8d2b94892a28c8e1ada3cfeeb with directory name What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
Thu Sep 12 23:01:18 2019	INFO	nzbToCouchPotato: [23:01:18] [DEBUG]::EXCEPTION: Replacing file name /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/63d178d8d2b94892a28c8e1ada3cfeeb.mkv with download name /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv
Thu Sep 12 23:01:18 2019	INFO	nzbToCouchPotato: [23:01:18] [INFO]::SUBTITLES: Attempting to download subtitles for /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv
Thu Sep 12 23:02:29 2019	INFO	nzbToCouchPotato: [23:02:29] [DEBUG]::COUCHPOTATO: Opening URL: https://couchpotato:443/api/e99caa31260c4bbb93382d486b9520ad/renamer.scan with PARAMS: {u'downloader': u'NZBGet', u'download_id': u'cecd85738c589d66fe16a117f8b0e9fd', u'media_folder': '/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)'}
Thu Sep 12 23:02:29 2019	INFO	nzbToCouchPotato: [23:02:29] [POSTPROCESS]::COUCHPOTATO: Starting renamer scan for What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: -- Cleaning bytecode --
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: WARNING: Automatic cleanup could not be executed.
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:          If errors occur, manual cleanup may be required.
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: REASON : Error: [Errno 2] No such file or directory
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Directory is not a git repository
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Force cleaning folder: libs
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Skipping required subfolders [u'common', u'custom', u'py2', u'win']
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Force cleaning folder: core
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Skipping required subfolders [u'auto_process', u'extractor', u'plugins', u'utils']
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Returning to directory:  /run/s6/services/nzbget
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: -- Cleanup finished --
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato: Traceback (most recent call last):
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:   File "/scripts/nzbToMedia/nzbToCouchPotato.py", line 272, in <module>
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:     result = nzbToMedia.main(sys.argv, section)
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:   File "/scripts/nzbToMedia/nzbToMedia.py", line 913, in main
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:     failure_link=failure_link)
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:   File "/scripts/nzbToMedia/nzbToMedia.py", line 803, in process
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:     result = movies.process(section_name, input_directory, input_name, status, client_agent, download_id, input_category, failure_link)
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:   File "/scripts/nzbToMedia/core/auto_process/movies.py", line 225, in process
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:     result = r.json()
Thu Sep 12 23:03:29 2019	INFO	nzbToCouchPotato:   File "/scripts/nzbToMedia/libs/common/requests/models.py", line 897, in json
Thu Sep 12 23:03:30 2019	INFO	nzbToCouchPotato:     return complexjson.loads(self.text, **kwargs)
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:   File "/usr/lib/python2.7/json/__init__.py", line 339, in loads
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:     return _default_decoder.decode(s)
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:   File "/usr/lib/python2.7/json/decoder.py", line 364, in decode
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:   File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato:     raise ValueError("No JSON object could be decoded")
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato: ValueError: No JSON object could be decoded
Thu Sep 12 23:03:31 2019	INFO	nzbToCouchPotato: Exception AttributeError: "'NoneType' object has no attribute 'path'" in <bound method PosixProcess.__del__ of <core.utils.processes.PosixProcess object at 0x14e70cdff610>> ignored
Thu Sep 12 23:03:31 2019	ERROR	Post-process-script nzbToCouchPotato.py for What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968) failed (terminated with unknown status)
Thu Sep 12 23:03:32 2019	INFO	Collection What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968) added to history

Sep 13 '19 04:09 death2all110

can you show CouchPotato logs at 23:02:29?

the issue here is the script crashed because CP never provides a valid response to say it received the rename command (this isn't a timeout, as the script receives a response, but it doesn't contain json data).

Looking at logs and times. I think your CP and NZBGet times are set different? CP snatches and sends to NZBGet, then renames the movie 3 minutes later, which is before NZBGet even starts to download?

Sep 14 '19 21:09 clinton-hall

Here are couchpotato logs for that time:

09-12 23:02:29 INFO
[tato.core.plugins.renamer] Scanning media folder /downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)...
09-12 23:02:29 INFO
[tato.core.plugins.scanner] Found 1 movies in the folder /downloads/completed/Movies
09-12 23:02:29 INFO
[hpotato.core.plugins.base] Opening url: get https://api.themoviedb.org/3/movie/tt7634968?api_key=xxx&append_to_response=alternative_titles&language=en, data: []
09-12 23:02:29 INFO
[hpotato.core.plugins.base] Opening url: get https://api.couchpota.to/info/tt7634968/?ignore=1, data: []
09-12 23:02:29 INFO
[hpotato.core.plugins.base] Opening url: get https://www.omdbapi.com/?apikey=xxx&type=movie&i=tt7634968, data: []
09-12 23:02:29 INFO
[ie.providers.info.omdbapi] Found: What Men Want (2019)
09-12 23:02:30 INFO
[tato.core.plugins.renamer] Same quality release already exists for What Men Want, with quality 720p. Assuming repack.
09-12 23:02:30 INFO
[tato.core.plugins.renamer] Removing "/movies/What Men Want (2019)/What Men Want.mkv"
09-12 23:02:30 INFO
[tato.core.plugins.renamer] Moving "/downloads/completed/Movies/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968)/What.Men.Want.2019.720p.BluRay.DD5.1.x264-FuzerHD-WhiteRev.cp(tt7634968).mkv" to "/movies/What Men Want (2019)/What Men Want.mkv"

Also, date command from Couchpotato:

root@959d746df070:/app/couchpotato# date
Sat Sep 14 20:12:22 CDT 2019

And NZBGet:

root@69ff9f978908:/# date
Sat Sep 14 20:12:34 CDT 2019

Apologies for the time discrepancies. There were a couple of attempts at downloading the movie, and I guess I didn't line the times up.

Also, I want to add that these are all setup with reverse proxies and couchpotato and nzbget(incl. nzbtomedia) are in their own docker containers.

Sep 15 '19 01:09 death2all110

looking at the code: r = requests.get(url, params=params, verify=False, timeout=(30, 1800)) the timeout is 30 seconds to attempt connection and 30 minutes to get a response...

according to the logs the script showed the error after 60 seconds, so the connection was made, and CouchPotato itself either returned non-valid data or cut the connection.

In this case it appears the rename did complete, and it is just the script that ended early?

Can you enable debug logging in nzbToMedia and CouchPotato and post full corresponding logs for each after next download?

Sep 15 '19 02:09 clinton-hall

Here is nzbget.log

Here is couchpotato.log

Here is nzbtomedia.log

The part for John Wick 2 can be disregarded. It was cleared from couchpotato before nzb completed, so that's my bad. But John Wick 3 failed.

Sep 15 '19 03:09 death2all110

ok... looked at this closely...

this time there was no error, or timeout... CP renamed the movie correctly. The script kept checking for 15 minutes. and then doesn't find any change....

but something is really funny here. It has all of the correct info for John Wick 3 when it sends to CP:

2019-09-14 22:06:13 POSTPROCESS::COUCHPOTATO: Starting renamer scan for John.Wick.Chapter.3.Parabellum.2019.2160p.10bit.WEB-DL.DDP5.1.Atmos.x265.HEVC-PSA.cp(tt6146586)

but when it looks for status chnage it is looking for John Wick 2

2019-09-14 22:08:25 POSTPROCESS::COUCHPOTATO: Checking for status change, please stand by ...
2019-09-14 22:08:25 DEBUG   ::MAIN: Opening URL: https://couchpotato.darkxshadows.net:443/api/e99caa31260c4bbb93382d486b9520ad/media.get with PARAMS: {u'id': 'tt4425200'}
...
2019-09-14 22:18:26 WARNING ::COUCHPOTATO: John.Wick.Chapter.2.2017.UHD.BluRay.2160p.TrueHD.Atmos.7.1.HEVC.REMUX-FraMeSToR.cp(tt4425200) does not appear to have changed status after 15 minutes, Please check your logs.

Notice the name and the IMDB ID have both changed.

In particular, with the input name, this is not updated or changed anywhere in the code between these 2 log sequences....

edit

I just realised the timing here. the logging at the end is from the first (John Wick 2) run. So the error from that run is printed into the logs from the second run, when in-fact the second run did again encounter the error where CP did not return json data.

This script should not be able to run 2 sessions simultaneously... both writing into the logs. I have never seen this... I wonder if the CP API is failing due to pile-up requests?

You may want to consider setting NZBGet to pause download while unpacking (settings, unpack, UnpackPauseQueue) and while executing scripts (settings, extension scripts, ScriptPauseQueue)... see if that makes any difference?

Sep 15 '19 10:09 clinton-hall

Unfortunately this didn't help :(

As I'm feeling like this is more of a CP issue at this point, and CP development is near dead, I'm testing Radarr. Sonarr works fine, so I expect this to be ok too. Will update shortly.

Sep 16 '19 02:09 death2all110

Unfortunately, I can't even seem to get Radarr and NZBget and these scripts to play nicely.

nzbToRadarr: [10:49:40] [ERROR]::MAIN: Category:[Movies] is not unique, ['CouchPotato', 'Radarr'] are using it. Please rename it or disable all other sections using the same category name in your autoProcessMedia.cfg and try again.

I've disabled CouchPotato in NZBGet and in autoprocessmedia.cfg, yet somehow Couchpotato is enabled again with all my details in the cfg under a [[Movies]] category.

I've disabled couchpotato as well., its not even running anymore.

I've even deleted the *.pyc files manually as well as deleted the nzbtomedia.db file thinking maybe those were holding stale config.

nzbget.conf autoprocessmedia.cfg

Thanks for all your help so far by the way.

Sep 16 '19 16:09 death2all110

The only reason I can see that this would happen is if the environment variables are still set (these should be refreshed on each run) but to be sure, I'd restart NZBGet to be sure nothing is being retained.

Basically, if the value is being re-written, it has to come from 1 of the following:

autoProcessMedia.cfg
autoProcessMedia.cfg.spec
Environment Variable NZBPO_CPSCATEGORY

This last one is supposed to only exist for the single child process (spawned by NZBGet) for each post-process event... however if somehow your system is launching multiple instances all under the same child process (which may explain the pile-up issues you had previously) then this will be holding the historical settings in the environment...

I have to say though, I have never seen this, so I can't begin to speculate how this may work...

If this is true then the last nzbToMedia log would have environment variable showing CPS variables... so search for NZBPO_CPSCATEGORY... if it exists, then that is what has gone wrong.

Sep 17 '19 01:09 clinton-hall

Success! autoProcessMedia.cfg.spec was the culprit. I re-ran post processing for one of the Radarr downloads and was successful. Thank you!

Sep 17 '19 03:09 death2all110

oh... interesting... I never considered that that may have been the culprit (it is a built in template and not supposed to be edited). Glad you have it working.... as a CP user myself I would have liked to have figured out why your combination wasn't playing nice.... but if Radarr is working for you... job done :)

Sep 17 '19 04:09 clinton-hall

Yeah it bugs me that I can't figure out what is going on with CP, as I prefer it. But oh well. Thanks for all your help!

I also edited the template by mistake instead of copying it when creating my config.

Sep 17 '19 22:09 death2all110

nzbToMedia nzbToMedia copied to clipboard

Postprocessing Fail with NZBGet, Couchpotato, and nzbToCouchPotato

nzbToMedia
nzbToMedia copied to clipboard