preprocessing stuck at 99% if incomplete on smb3

[defkev]

So a friend of mine got crazy with all the WannaCrypt nonsense, i told her to Windows Update and disable SMB1 and call it a day.
Shortly after she told me sabnzbd is no longer working...i really need to stop telling ppl what software i use personally
Shes running sab on a bananapi with a mount point to her windows box for sabs complete/incomplete stuff which of course was no longer accessible after disabling SMB1, added vers=3.0 to fstab, mount -a and all good - at least thats what i thought.

Now i'm sitting here and scratching my head over something which just doesn't make any sense at all.

With the incomplete folder on a cifs share using anything but SMBv1 and opt-pre_check enabled all downloads will get stuck at 99% during preprocessing, sab will remove any and all SABnzbd_nzf and nzo from the JOB_ADMIN folder leaving only the nzb.gz and SABnzbd_attrib behind and literally wait infinite for the end of days.
If i either disable opt-pre_check or mount using SMBv1 the preprocessing completes as expected and the download starts.

Log from running sab on cli with logging 2 (obfuscate because paranoia)

Code: Select all

2017-05-14 00:07:05,908::INFO::[__init__:677] Adding 10MB.nzb
2017-05-14 00:07:05,912::INFO::[misc:891] Creating directories: /mnt/Downloads/incomplete/10MB.1
2017-05-14 00:07:05,919::DEBUG::[__init__:899] Saving data for SABnzbd_nzf_mZ2D0c in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:05,922::INFO::[nzbstuff:467] File (t) [3/3] - "data_10mb.part3.rar" yEnc (1/1) added to queue
2017-05-14 00:07:05,924::DEBUG::[__init__:899] Saving data for SABnzbd_nzf_IDMLur in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:05,927::INFO::[nzbstuff:467] File (t) [2/3] - "data_10mb.part2.rar" yEnc (1/14) added to queue
2017-05-14 00:07:05,929::DEBUG::[__init__:899] Saving data for SABnzbd_nzf_qjF_rY in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:05,932::INFO::[nzbstuff:467] File (t) [1/3] - "data_10mb.part1.rar" yEnc (1/14) added to queue
2017-05-14 00:07:05,933::DEBUG::[nzbstuff:497] META-DATA = {}
2017-05-14 00:07:05,933::INFO::[__init__:620] Backing up /mnt/Downloads/incomplete/10MB.1/__ADMIN__/10MB.nzb.gz
2017-05-14 00:07:05,940::INFO::[nzbqueue:254] Saving queue
2017-05-14 00:07:05,943::DEBUG::[__init__:899] Saving data for SABnzbd_nzo_NjNxaj in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:05,948::INFO::[__init__:971] Saving data for queue10.sab in /home/sabuser/.sabnzbd/admin/queue10.sab
2017-05-14 00:07:05,949::DEBUG::[nzbstuff:235] Finishing import on (t) [1/3] - "data_10mb.part1.rar" yEnc (1/14)
2017-05-14 00:07:05,951::DEBUG::[__init__:933] Loading data for SABnzbd_nzf_qjF_rY from /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_qjF_rY
2017-05-14 00:07:05,952::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,172::INFO::[happyeyeballs:138] Quickest IP address for awesome.usenet.provider (port 563, ssl 1, preferipv6 True) is 127.0.0.1
2017-05-14 00:07:06,173::DEBUG::[happyeyeballs:140] Happy Eyeballs lookup and port connect took 80 ms
2017-05-14 00:07:06,173::DEBUG::[downloader:132] awesome.usenet.provider: Connecting to address 127.0.0.1
2017-05-14 00:07:06,193::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,194::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,214::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,214::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,234::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,235::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,255::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,256::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,276::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,277::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,296::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,297::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,318::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,318::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,340::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,340::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,361::INFO::[downloader:491] [email protected]: Initiating connection
2017-05-14 00:07:06,361::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,362::DEBUG::[downloader:113] awesome.usenet.provider: Re-using address 127.0.0.1
2017-05-14 00:07:06,385::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,445::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,451::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,458::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,489::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,503::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,517::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,538::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,565::INFO::[newswrapper:124] [email protected]: Connected using TLSv1 (RC4-SHA)
2017-05-14 00:07:06,576::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,616::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,617::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,629::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,670::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,672::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,672::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,681::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,684::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,687::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,714::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,714::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,716::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,726::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,727::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,745::INFO::[downloader:704] Connecting [email protected] finished
2017-05-14 00:07:06,813::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,814::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,876::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,877::DEBUG::[nzbstuff:235] Finishing import on (t) [2/3] - "data_10mb.part2.rar" yEnc (1/14)
2017-05-14 00:07:06,878::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,878::DEBUG::[__init__:933] Loading data for SABnzbd_nzf_IDMLur from /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_IDMLur
2017-05-14 00:07:06,898::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,899::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,933::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,934::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,950::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,951::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,957::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,958::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,959::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,960::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,972::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,972::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,974::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,975::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,977::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,977::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:06,991::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:06,991::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,026::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,040::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,082::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,082::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,151::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,152::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,168::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,169::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,175::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,176::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,176::DEBUG::[nzbstuff:235] Finishing import on (t) [3/3] - "data_10mb.part3.rar" yEnc (1/1)
2017-05-14 00:07:07,179::DEBUG::[__init__:933] Loading data for SABnzbd_nzf_mZ2D0c from /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_mZ2D0c
2017-05-14 00:07:07,192::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,192::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,209::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,210::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,251::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,251::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,318::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,319::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,440::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,441::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,441::DEBUG::[nzbstuff:1254] Download Quality: enough=True, have=10870230, need=10870230, ratio=1.0
2017-05-14 00:07:07,442::DEBUG::[__init__:899] Saving data for SABnzbd_nzo_NjNxaj in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:07,451::INFO::[__init__:971] Saving data for totals10.sab in /home/sabuser/.sabnzbd/admin/totals10.sab
2017-05-14 00:07:07,480::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,480::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,547::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,548::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,549::DEBUG::[nzbstuff:1254] Download Quality: enough=True, have=10870230, need=10870230, ratio=1.0
2017-05-14 00:07:07,549::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,550::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,578::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,578::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,625::DEBUG::[downloader:709] Article <[email protected]> is present
2017-05-14 00:07:07,625::DEBUG::[decoder:174] Server awesome.usenet.provider:563 has article [email protected]
2017-05-14 00:07:07,626::DEBUG::[nzbstuff:1254] Download Quality: enough=True, have=10870230, need=10870230, ratio=1.0
2017-05-14 00:07:07,630::DEBUG::[__init__:899] Saving data for SABnzbd_nzo_NjNxaj in /mnt/Downloads/incomplete/10MB.1/__ADMIN__
2017-05-14 00:07:07,637::DEBUG::[nzbstuff:1254] Download Quality: enough=True, have=10870230, need=10870230, ratio=1.0
2017-05-14 00:07:07,638::INFO::[__init__:962] /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_mZ2D0c removed
2017-05-14 00:07:07,640::INFO::[__init__:962] /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_qjF_rY removed
2017-05-14 00:07:07,642::INFO::[__init__:962] /mnt/Downloads/incomplete/10MB.1/__ADMIN__/SABnzbd_nzf_IDMLur removed
2017-05-14 00:07:08,626::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:08,729::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:08,832::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:08,936::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,039::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,142::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,246::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,349::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,453::INFO::[downloader:789] Thread [email protected]: forcing disconnect
2017-05-14 00:07:09,556::INFO::[downloader:789] Thread [email protected]: forcing disconnect

[sander]

Interesting!

To be sure: with opt-pre_check you mean "Check before download. Try to predict successful completion before actual download (slower!)"?

SAB uses python-calls (and maybe directly OS-calls) to write and read stuff. So maybe there is something SMB1 specific in there?
I must say I would be surprised if pre_check would do any file writing. But let's find out.

a mount point to her windows box for sabs complete/incomplete stuff

What if you put Incomplete on the Bananapi (and not on Windows) so that we can pinpoint if the stuck is in Incomplete or Complete?

Where (at what time) in your logging does the stuck occur?

FWIW: I have one Windows computer at home, but I can't even connect from my Linux to that Windows share, because of all the common SMB/Samba error messages ...

[defkev]

To be sure: with opt-pre_check you mean "Check before download. Try to predict successful completion before actual download (slower!)"?

Yes, under Config -> Switches -> Queue

What if you put Incomplete on the Bananapi (and not on Windows) so that we can pinpoint if the stuck is in Incomplete or Complete?

Ah sorry, forgot to mention that i already tried that and it did work. Unfortunately the root filesystem is fairly small so not a viable workaround.

Where (at what time) in your logging does the stuck occur?

The last line, i even let it stay like this for at least 15 minutes but nothing happens. The frontend will sit at 99% and no further logging on the console.

[defkev]

I was able to reproduce this in a VM using the latest Release of SABnzbd from Github, the complete/incomplete folder is a SMB share on the host running Windows 10 with SMBv1 disabled (again using vers=3.0 in fstab on the guest)

https://gfycat.com/FantasticAdolescentFlyingfish

Edit:
Did another run with --logging set to 2, you can see the pre_check taking place/succeeding and then a whole lot of nothing.

[sander]

Finally I was able to access a Windows 7 share, which was writable:

Code: Select all

sudo mount.cifs //192.168.0.114/bla ~/bla -o user=John,password=verysecret,file_mode=0777,dir_mode=0777

It works with default settings.

After turning off SMB1 on the Windows 7, I get this:

Code: Select all

sander@flappie:~$ sudo mount.cifs //192.168.0.114/bla ~/bla -o user=John,password=verysecret,file_mode=0777,dir_mode=0777
mount error(112): Host is down
Refer to the mount.cifs(8) manual page (e.g. man mount.cifs)

So far, so good. Now find the smb3 option in linux ...

[sander]

How can I enable SMB2/SMB3 on the Linux client side?

I tried the below in /etc/samba/smb.conf, but I still can't access the Windows 7 (with SMB1 disabled)

[global]

min protocol = LANMAN2
max protocol = SMB3

[defkev]

Just add vers=3.0 (or 2.0/2.1 depending on your Windows Version) to the mount options, e.g.

Code: Select all

sudo mount.cifs //192.168.0.114/bla ~/bla -o user=John,password=verysecret,file_mode=0777,dir_mode=0777,vers=3.0

Make sure to umount before remounting.

[sander]

Thanks. I had to do "vers=2.1" because it is a Win7 I'm talking too.

Back to SAB: I can reproduce the problem. Sometimes SAB hangs at 99% pre-checking (in Blue), sometimes at 100% (pre-checking completed, in Green).



So: reproducible. Now find the root cause in SAB ...

EDIT:

For one download, SAB says:

Code: Select all

2017-05-15 08:04:42,292::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_sizOmS)

[sander]

A quick note about my current hypothesis: "SAB's pre-check does a file/directory-call that leads to a hang/time-out if SMB1 is not there. It might be a bug or something special in the SAB code, or in Python, or in underlying system calls."

EDIT:

Intresting if the only happens with Linux as client & Windows as server, or also with variants like Windows as client & server, etc.

[defkev]

Ok, i think i found "it"

The problem is in misc.py in the remove_all function around line 1416:

Code: Select all

def remove_all(path, pattern='*', keep_folder=False, recursive=False):
  ...
  if not keep_folder:
    try:
      os.rmdir(path)
    except:
      logging.info('Cannot remove folder %s', path)

Called by nzbstuff.py __init__ around line 672:

Code: Select all

  ...
  if reuse:
    remove_all(adir, 'SABnzbd_nz?_*')
    remove_all(adir, 'SABnzbd_article_*')
  ...

Well its not really a problem with sabnzbd or python but how rmdir's behavior differs between a local/SMBv1 and a SMBv3 mount.

On a local/SMBv1 mount rmdir on a non-empty folder will fail with:

Code: Select all

rmdir: failed to remove '/path/to/non/empty/folder': Directory not empty

This is pretty much the POSIX expected behavior, rmdir will exit non-zero and cause the exception to be triggered

Now on a SMBv3 mount rmdir will return nothing and exit zero (causing the function to complete) even true the directory didn't get removed.

I have never seen this before and its imho a awfully weird behavior of rmdir.

Now to work around this i can simply change both remove_all calls in nzbstuff.py to

Code: Select all

remove_all(adir, 'SABnzbd_nz?_*', True)
remove_all(adir, 'SABnzbd_article_*', True)

and skip the rmdir call all together which will cause the download to get moved into the queue after preprocessing and complete as expected.

Dunno if this is a viable option or you would be better of doing some more chechking in misc.py after calling os.rmdir?

[sander]

I tried this:

Code: Select all

        if reuse:
            '''
            remove_all(adir, 'SABnzbd_nz?_*')
            remove_all(adir, 'SABnzbd_article_*')
            '''
            remove_all(adir, 'SABnzbd_nz?_*', True)
            remove_all(adir, 'SABnzbd_article_*', True)

and the pre-check works, and the download too. Nice!

I still have to understand your post and the code. For example: why does SAB remove that directory? Is that because the dir is created for the pre-check?

FWIW: My focus was/is on these messages that appear since turning off SMB1:

Code: Select all

$ cat .sabnzbd/logs/sabnzbd.log* | grep "Failed to find" | sort
2017-05-15 07:48:36,158::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_t534f2)
2017-05-15 07:49:28,541::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_jnAggi)
2017-05-15 07:58:38,039::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_ZSQaKf)
2017-05-15 08:04:42,292::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_sizOmS)
2017-05-15 08:25:10,629::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_m5hqxH)
2017-05-15 08:30:50,230::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_Af63AR)
2017-05-15 08:34:16,117::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_aG2bkM)
2017-05-15 08:40:03,222::DEBUG::[nzbqueue:218] Failed to find NZB file after pre-check (SABnzbd_nzo_ZhxL3_)
2017-05-15 17:45:17,504::DEBUG::[nzbqueue:221] Failed to find NZB file after pre-check (SABnzbd_nzo_qqVXXA)
2017-05-15 17:49:55,410::DEBUG::[nzbqueue:188] Failed to find NZB file after pre-check (SABnzbd_nzo__f0iwh)

[defkev]

Sorry, change False to True (already edited my reply) so not keep_folder gets skipped in misc.py

My bad

[sander]

These CLI tests confirm your post's statement:

Code: Select all

# Plain ext4 , non-empty directory
sander@flappie:~$ rmdir test123/ ; echo $?
rmdir: failed to remove ‘test123/’: Directory not empty
1

Code: Select all

# SMB2.1, non-empty directory
sander@flappie:~$ ll bla/Downloads/ 
total 4
drwxrwxrwx 2 root root    0 mei 15 08:50 ./
drwxrwxrwx 2 root root 4096 mei 15 08:39 ../
-rwxrwxrwx 1 root root    0 mei 14 23:50 bla*
drwxrwxrwx 2 root root    0 mei 15 10:58 complete/
drwxrwxrwx 2 root root    0 mei 15 10:58 incomplete/

sander@flappie:~$ rmdir bla/Downloads/ ; echo $?
0

sander@flappie:~$ ll bla/Downloads/ 
total 4
drwxrwxrwx 2 root root    0 mei 15 08:50 ./
drwxrwxrwx 2 root root 4096 mei 15 08:39 ../
-rwxrwxrwx 1 root root    0 mei 14 23:50 bla*
drwxrwxrwx 2 root root    0 mei 15 10:58 complete/
drwxrwxrwx 2 root root    0 mei 15 10:58 incomplete/
sander@flappie:~$ 

EDIT:

Wow, even on Win7 itself:

Code: Select all

C:\>rmdir bla2
The directory is not empty.

C:\>echo %errorlevel%
9009


Z:\>rmdir Downloads
The directory is not empty.

Z:\>echo %errorlevel%
0

Z:\>

[defkev]

Dunno, whats the intent of reuse?
Its not a user configurable option from what i can tell looking at the code.

Regardless removing the JOB_ADMIN/working directory of a incomplete download doesn't make much sense in my book either, i mean you would need to recreate it anyway since it is pretty mandatory even if you store all articles in memory.
Thats what i do (article cache limit set to 1GB) to limit disk read/writes.

[defkev]

Looks like "rm -df" works consistent across local/SMBv1 up to SMBv3 and always returns 1 if the directory isn't empty.

Unfortunately this isn't cross platform compatible.