Jobs won't fail depending on availability

[yell0]

Any idea if this is a bug, or I can do something about it?

[safihre]

Unfortunately I'm not sure, but if it was a common bug I would have expected many more posts about it.

[yell0]

Interesting... just found out SABnzbd can remove the orphaned jobs entirely when deleting manually through the "orphaned jobs" section of the interface.

So SABnzbd does have correct permissions to remove the files, it just doesn't. Any way I can find out why? Or should I wait until you make SAB log the reason?

[safihre]

It's most likely a timing issue, that the disk thinks it's still busy (because it's external drive, it has more latency).
You can change the code yourself to see the exact reason.
In sabnzbd/nzbstuff.py change line 1784 from:

Code: Select all

                    logging.debug('Folder not removed: %s', self.downpath)

to

Code: Select all

                    logging.debug('Folder not removed: %s', self.downpath, exc_info=True)

It will then show it when you have +Debug turned on.
(you should now be able to post logs)

[yell0]

Changed the line, now debug log shows:

Code: Select all

2019-03-28 13:48:18,098::INFO::[postproc:340] Starting Post-Processing on JobName => Repair:True, Unpack:True, Delete:True, Script:None, Cat:other
2019-03-28 13:48:18,105::INFO::[postproc:558] Cleaning up JobName (keep_basic=True)
2019-03-28 13:48:18,106::INFO::[nzbstuff:1759] [sabnzbd.nzbqueue.cleanup_nzo] Purging data for job JobName (keep_basic=True, del_files=False)
2019-03-28 13:48:18,109::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,111::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,112::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,114::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,116::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,118::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,120::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,122::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,124::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,126::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,128::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,129::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,131::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,133::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,134::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,136::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,138::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,140::DEBUG::[misc:1205] [sabnzbd.remove_data] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,146::DEBUG::[misc:1205] [sabnzbd.misc.remove_all] Deleting file /FolderName/__ADMIN__/FileName
2019-03-28 13:48:18,149::DEBUG::[misc:1161] [sabnzbd.nzbstuff.purge_data] Deleting dir FolderName
2019-03-28 13:48:18,151::DEBUG::[nzbstuff:1786] Folder not removed: FolderName
Traceback (most recent call last):
  File "/usr/share/sabnzbdplus/sabnzbd/nzbstuff.py", line 1784, in purge_data
    remove_dir(self.downpath)
  File "/usr/share/sabnzbdplus/sabnzbd/decorators.py", line 36, in call_func
    return f(*args, **kw)
  File "/usr/share/sabnzbdplus/sabnzbd/misc.py", line 1177, in remove_dir
    os.rmdir(path)
OSError: [Errno 39] Directory not empty: 'FolderName'
2019-03-28 13:48:18,239::INFO::[database:272] Added job JobName to history
2019-03-28 13:48:18,241::INFO::[database:261] Removing all but last 20 completed jobs from history
2019-03-28 13:48:18,306::INFO::[postproc:94] Saving postproc queue
2019-03-28 13:48:18,307::DEBUG::[__init__:959] [sabnzbd.postproc.save] Saving data for postproc2.sab in /config/admin/postproc2.sab
2019-03-28 13:48:18,310::INFO::[downloader:301] Post-processing finished, resuming download
2019-03-28 13:48:18,572::DEBUG::[bpsmeter:268] bps: 3587327.93147

[safihre]

Ah, yes this happens when using external storage (USB or NAS) for the Incomplete folder.
We tell the operating system to delete all the files, but because of the delay due the USB/network the files are not deleted yet when we try to remove the folder.
We could add some retries, but in general you shouldn't use external storage for incomplete folder.

[yell0]

Can't use SATA drives with my device, and putting incomplete folder on the micro-SD card with OS makes it unusable and sometimes crash.
Haven't had any problems with USB external drives apart from deleting in this scenario, it's impractical in most cases but anyone using a small device has to do this.
Would you consider adding retries? Also many thanks for finding the issue.