Closed Nemesis001 closed 7 years ago
SickRage added a post-processing queuing function with the latest git update, so I'm guessing the new return code for "added to the post-processing queue" isn't what nzbtomedia expects, and nzbtomedia needs an update?
Edit:
I looked at the log format before and after updates and I believe the updated SickRage logging format isn't currently matching nzbtomedia AutoProcessTV.py:
Old:
2017-01-02 17:05:41 INFO Thread-27 :: Processing succeeded for <path>
2017-01-02 17:05:41 INFO Thread-27 :: Deleting folder <path>
2017-01-02 17:05:41 INFO Thread-27 :: Successfully processed
Matches this section from AutoProcessTV.py
if section == "SickBeard":
for line in r.iter_lines():
if line:
logger.postprocess("%s" % (line), section)
if "Moving file from" in line:
inputName = os.path.split(line)[1]
if "Processing succeeded" in line or "Successfully processed" in line:
Success = True
New (the lines no longer have a Thread-# prefix
2017-01-05 13:23:41 INFO POSTPROCESSOR-AUTO :: Processing succeeded for <path>
2017-01-05 13:23:41 INFO POSTPROCESSOR-AUTO :: Deleting folder (if it's empty): <path>
2017-01-05 13:23:41 INFO POSTPROCESSOR-AUTO :: Successfully processed
2017-01-05 13:23:41 INFO POSTPROCESSOR-AUTO :: Auto post processing task for <path> completed
I'm guessing the change from Thread-# to PostProcessor-Auto is the culprit here, because the order and phrasing of the rest of the log is the same.
The Thread-#
to PostProcessor-Auto
isn't an issue. in both logs shown above both Processing succeeded
and Successfully processed
are returned.
The issue with the first log (in the original post) is that SickRage only returned
Auto post processing task for \\san\media\Multimedia\New.Girl.S06E11.Raisins.Back.720p.WEB-DL.DD5.1.H.264-CLZ was added to the queue
So I am guessing, when the queue is empty, the returned logging is ok, but when there is more going on, and SickRage queues the process, this doesn't return anything useful.
The big problem is I can't just say it is good if SickRage says the process is queued, because there are other processes that follow, like resuming torrents or deleting, and I need to know SickRage has finished renaming etc first...
I am wondering if there needs to be an option to say "don't queue" when sending to SickRage, and just keep the connection open until it has finished...??
Which Branch/fork of SickRage is this on?
https://github.com/SickRage/SickRage/commit/5cc4f54739ccd020c584367f9f07799cb827fc4a is the current commit my instance is on.
I don't see any General or Post-Processing setting to disable the new queue function.
It appears that even the first item to go into the empty queue uses the new logging line format:
2017-01-05 13:14:04 INFO TORNADO :: User logged into the SickRage web interface
2017-01-05 13:14:07 INFO TORNADO :: User logged into the SickRage web interface
2017-01-05 13:14:08 INFO Thread-29 :: Auto post processing task for D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV was added to the queue
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: Beginning auto post processing task: D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: PostProcessing Path: D:\sabnzbd\Downloads\complete\tv
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: Processing D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV\The.Expanse.S01E01.720p.HDTV.x264-BATV.mkv (The.Expanse.S01E01.720p.HDTV.x264-BATV.nzb)
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: This download is marked a priority download so I'm going to replace an existing file if I find one
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: Process method is 'move' and src and destination are on the same device, skipping free space check
2017-01-05 13:14:08 INFO POSTPROCESSOR-AUTO :: Using nzb_name for release name.
2017-01-05 13:14:09 INFO POSTPROCESSOR-AUTO :: 280619: Changed modify date of 'The Expanse - S01E01 - 720p HDTV.mkv' to show air date Dec 14,2015 (22:00)
2017-01-05 13:14:09 INFO POSTPROCESSOR-AUTO :: Processing succeeded for D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV\The.Expanse.S01E01.720p.HDTV.x264-BATV.mkv
2017-01-05 13:14:09 INFO POSTPROCESSOR-AUTO :: Deleting folder (if it's empty): D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV
2017-01-05 13:14:09 INFO POSTPROCESSOR-AUTO :: Successfully processed
2017-01-05 13:14:09 INFO POSTPROCESSOR-AUTO :: Auto post processing task for D:\sabnzbd\Downloads\complete\tv\The Expanse S01E01 720p HDTV x264-BATV completed
Yea, I just ran into this issue as well and was about to post an issue about it. The PP is fine, it's just the return code is PP-Failure in NZBGet. I hope it gets sorted out with the SickRage guys. Thanks for all your work Clinton.
Same issue over here. Possible (maybe bad) idea for a workaround if Sickrage doesn't fix this. Could the script submit the task to the queue, and then watch the SR logs until the appropriate "Processing Succeeded" line shows up?
The issue has been temporarily fixed in the latest commit of SickRage: https://github.com/SickRage/SickRage/commit/203d7b4ce1f0020bca2da75a796c8510c6a79b07
However, I've observed that this has caused a race condition when force_clean=1 where the files that are queued for postprocessing are deleted by nzbToMedia before SickRage gets a chance to process them. Setting force_clean=0 works, but leaves behind a pile of cruft that needs to be manually deleted, since SABnzbd and other downloaders won't delete leftover files if the post-download script executes successfully (errorcode 0).
Something to keep in mind for the hopefully forthcoming patch.
Update: Seems that failed download handling has been totally broken as well. This is probably more of an issue for the SickRage developers, but in either case, failed nzbs in SABnzbd are not being added to the failed downloads table, nor are they marked as such in the history.
I can confirm as well.
This is due to the new post processing queue in SickRage, which solves a whole slew of other issues in SickRage that are caused when auto/manual/api post processing is called on top of each other or more than once each. Now, instead of returning the log of the task you started it can only return whether the task was added to the queue or not, and the task will run as soon as the previous task completes.
The string nzbtomedia checks for on success I have added as a hidden string in the html so the call from nzbtomedia succeeds, but nzbtomedia should not be deleting any files. I have fixed that problem in the post processor on windows where users had to use copy instead of move to get the correct permissions, which left files behind after the copy ofcourse. They can now check the icacls option in the post processor and use the move method now and the files will be deleted as they should be automatically.
Make sure force_clean=0 in nzbtomedia, and wait for the task to complete.
What's the proper guidance now, for interaction between sab, nzbtomedia, and sickrage?
Should the box at the top of SickRage Post-Processing be checked or not?
When it wasn't checked, nzbtomedia script reports success, and sickrage reports that the folder/file is queued, but nothing happens. Now with force_clean=0, the file isn't deleted by nzbtomedia, but it isn't moved either.
I tried kicking things lose with Manual Post-Processing and all that did was report "yes, this has been queued".
It wasn't until I checked the box at the top of the Post Processing settings (which the page tells you not to do if using an external script (nzbtomedia) that things sorta work. But I'm also getting a lot of failures that report that the file is locked for reading/writing:
2017-01-08 21:32:14 INFO TORNADO :: User logged into the SickRage web interface
2017-01-08 21:32:15 INFO Thread-25 :: Auto post processing task for D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION was added to the queue
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: Beginning auto post processing task: D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: PostProcessing Path: D:\sabnzbd\Downloads\complete\tv
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: Processing D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION\NCIS.Los.Angeles.S08E12.720p.HDTV.X264-DIMENSION.mkv (NCIS.Los.Angeles.S08E12.720p.HDTV.X264-DIMENSION.nzb)
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: This download is marked a priority download so I'm going to replace an existing file if I find one
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: Process method is 'move' and src and destination are on the same device, skipping free space check
2017-01-08 21:32:16 INFO POSTPROCESSOR-AUTO :: Using nzb_name for release name.
2017-01-08 21:32:17 WARNING POSTPROCESSOR-AUTO :: Processing failed for D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION\NCIS.Los.Angeles.S08E12.720p.HDTV.X264-DIMENSION.mkv: File is locked for reading/writing
2017-01-08 21:32:17 WARNING POSTPROCESSOR-AUTO :: Problem(s) during processing, failed the following files/folders:
2017-01-08 21:32:17 WARNING POSTPROCESSOR-AUTO :: [D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION\NCIS.Los.Angeles.S08E12.720p.HDTV.X264-DIMENSION.mkv : Processing failed: File is locked for reading/writing]
2017-01-08 21:32:17 INFO POSTPROCESSOR-AUTO :: Auto post processing task for D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION completed
Hmm, it looks like nzbtomedia is still firing CLEANDIRS, even with force_clean=0 set.
2017-01-08 21:32:08 INFO ::MAIN: Script triggered from SABnzbd 0.7.17+
2017-01-08 21:32:10 INFO ::MAIN: Auto-detected SECTION:SickBeard
2017-01-08 21:32:10 INFO ::MAIN: Calling SickBeard:tv to post-process:NCIS.Los.Angeles.S08E12.720p.HDTV.X264-DIMENSION.nzb
2017-01-08 21:32:11 INFO ::MAIN: Attempting to auto-detect tv fork
2017-01-08 21:32:13 INFO ::MAIN: SickBeard:tv fork auto-detection successful ...
2017-01-08 21:32:13 INFO ::MAIN: SickBeard:tv fork set to sickragetv
2017-01-08 21:32:13 INFO ::MAIN: FLATTEN: Flattening directory: D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION
2017-01-08 21:32:13 POSTPROCESS::SICKBEARD: SUCCESS: The download succeeded, sending a post-process request
2017-01-08 21:32:15 POSTPROCESS::SICKBEARD: Auto post processing task for D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION was added to the queue
2017-01-08 21:32:15 POSTPROCESS::SICKBEARD: <br\><span class='hidden'>Processing succeeded</span>
2017-01-08 21:32:16 INFO ::CLEANDIRS: Directory D:\sabnzbd\Downloads\complete\tv\NCIS Los Angeles S08E12 720p HDTV X264-DIMENSION has been processed, removing ...
2017-01-08 21:32:17 INFO ::MAIN: The D:\SickRage\contrib\nzbToMedia\nzbToSickBeard.py script completed successfully.
Cleandirs is always triggered, but no media files are deleted unless force_clean = 1
The issues I need to work through here are how to handle the new queue feature with torrents etc. The problem here is that I stop the torrent client from seeding to avoid any file locks, but once successful rename by SickBeard/SickRage/CouchPotato etc it then resumes seeding, or deletes the torrent.
In this case, when queued, we can't resume seeding or remove the torrent until we have verified that the rename event has been completed. Also, when using move-sym
the original file is moved and a symlink created to point to that location. now, once the rename has completed, the script will transverse the links and make the original torrent location link direct to the end library file... again, this all needs to be done when the rename event has completed.
I'll try and have a solution to this shortly.
So do you believe that it's not NZBtoMedia causing the SickRage processing failure where it's reporting that the "file is locked for reading/writing"?
Or is it your belief that it is, and you're having to fix the NZBtoMedia script to pause until the true end of the PP auto-process queue completion and the move/rename has truly finished from the SickRage side?
I believe in this case it does appear that nzbToMedia has deleted the file before it was processed. I am looking to see ho cleandirs is functioning, as I didn't think this deleted media files... but it appears it did.
I am also discussing this with miigotu to determine how to best handle this
Great. Standing by!
Confirmed that the latest SR + nightly nzbToMedia has things back to normal.
heymoe, have you tested whether we can safely set force_clean = 1 without any problems?
@drspangle I have force_clean = 1 with latest SR and nightly nzbToMedia and it works for me. Haven't experienced anything else at least.
Yep, set force_clean back to 1 and all is working like it did before.
Trying to figure out where this is coming from. Most posts on the issue mention to make sure SickRage and nzbToMedia are up to date. Tried both with fork set to auto and sickrage. Nothing works.
Not much I can gather from the log:
This is the configuration file:
Any suggestion where should I look further?
Thanks,