Downloads stop with "ENCRYPTED" proper password is already supplied

[ZlatkO]

I've noticed that with 3.1.0 it happens more often again that downloads are stopped/paused with "ENCRYPTED" when they are in fact not. Well, they actually are, of course, but the proper password is already supplied and known to SABnzbd. When this happens, all I have to do is to klick the "Play/Continue" button, and SABnzbd goes on as usual, downloads the rest and unpacks the RAR just fine. I do not have to change/reenter the password, this works fine with exactly the same data that SABnzbd started with right from the beginning.

Unfortunately this problem is not reproducible. As I said, once I klick "continue" without adding/changing anything else, everything works just fine. If I try to download the exact same NZB once again, usually everything works just fine as well. One thing that I did notice, however, is that SABnzbd seems to have to go and get some additional PAR2 files and do a little repair before the original paused & continued download can be unpacked. So this is probably somehow related ... maybe SABnzbd thinks it has a wrong password, when in fact it has only downloaded a broken/incomplete RAR?

SABnzbd 3.1.0 running on Linux (Slackware 14.2 i686), download dir is on NFS (provided by a QNAP NAS).

Startup log:

Code: Select all

2020-10-20 22:33:29,852::INFO::[SABnzbd:1142] --------------------------------
2020-10-20 22:33:29,853::INFO::[SABnzbd:1143] SABnzbd.py-3.1.0 (rev=23f86e95f1f980963c4e4017276b3a3e2adfc6e2)
2020-10-20 22:33:29,853::INFO::[SABnzbd:1144] Full executable path = /usr/local/stow/SABnzbd-3.1.0/lib/python3.8/site-packages/SABnzbd-3.1.0/SABnzbd.py
2020-10-20 22:33:29,854::INFO::[SABnzbd:1154] Platform = posix
2020-10-20 22:33:29,854::INFO::[SABnzbd:1155] Python-version = 3.8.5 (default, Sep 22 2020, 05:50:13) 
[GCC 5.5.0]
2020-10-20 22:33:29,854::INFO::[SABnzbd:1156] Arguments = "./SABnzbd.py" "-d" "-f" "/home/zlatko/.sabnzbd/sabnzbd.ini" "--pidfile" "/var/local/run/sabnzbd/sabnzbd-9090.pid"
2020-10-20 22:33:29,854::INFO::[SABnzbd:1160] Not inside a docker container
2020-10-20 22:33:29,854::INFO::[SABnzbd:1163] Preferred encoding = UTF-8
2020-10-20 22:33:29,854::INFO::[SABnzbd:1179] SSL version = OpenSSL 1.1.1g  21 Apr 2020
2020-10-20 22:33:29,858::INFO::[SABnzbd:1188] Certifi version: 2017.11.05
2020-10-20 22:33:29,858::INFO::[SABnzbd:1189] Loaded additional certificates from: /usr/local/lib/python3.6/site-packages/certifi/cacert.pem
2020-10-20 22:33:29,858::INFO::[SABnzbd:1234] Using INI file /home/zlatko/.sabnzbd/sabnzbd.ini
2020-10-20 22:33:29,874::INFO::[postproc:140] Loading postproc queue
2020-10-20 22:33:29,875::INFO::[__init__:951] [N/A] /home/zlatko/.sabnzbd/admin/Rating.sab missing
2020-10-20 22:33:29,876::INFO::[scheduler:216] Setting schedule for midnight BPS reset
2020-10-20 22:33:29,876::INFO::[__init__:349] All processes started
2020-10-20 22:33:29,877::INFO::[SABnzbd:297] Template location for Glitter is /usr/local/stow/SABnzbd-3.1.0/lib/python3.8/site-packages/SABnzbd-3.1.0/interfaces/Glitter
2020-10-20 22:33:29,877::INFO::[SABnzbd:297] Template location for Config is /usr/local/stow/SABnzbd-3.1.0/lib/python3.8/site-packages/SABnzbd-3.1.0/interfaces/Config
2020-10-20 22:33:29,878::INFO::[misc:986] [N/A] Running external command: ['/usr/bin/nice', '-n', '10', '/usr/bin/ionice', '-c2', '-n4', '/usr/local/bin/unrar']
2020-10-20 22:33:29,900::INFO::[misc:986] [N/A] Running external command: ['/usr/bin/nice', '-n', '10', '/usr/bin/ionice', '-c2', '-n4', '/usr/local/bin/par2_tbb', '-h']
2020-10-20 22:33:29,920::INFO::[SABnzbd:398] SABYenc module (v4.0.2)... found!
2020-10-20 22:33:29,921::INFO::[SABnzbd:417] Cryptography module (v3.1.1)... found!
2020-10-20 22:33:29,921::INFO::[SABnzbd:422] par2 binary... found (/usr/local/bin/par2_tbb)
2020-10-20 22:33:29,921::INFO::[SABnzbd:429] UNRAR binary... found (/usr/local/bin/unrar)
2020-10-20 22:33:29,921::INFO::[SABnzbd:439] UNRAR binary version 5.50
2020-10-20 22:33:29,922::INFO::[SABnzbd:447] 7za binary... found (/usr/local/bin/7za)
2020-10-20 22:33:29,922::INFO::[SABnzbd:458] nice binary... found (/usr/bin/nice)
2020-10-20 22:33:29,922::INFO::[SABnzbd:462] ionice binary... found (/usr/bin/ionice)
2020-10-20 22:33:29,926::INFO::[SABnzbd:1293] HTTPS keys are OK
2020-10-20 22:33:29,932::INFO::[SABnzbd:1421] Starting web-interface on 127.0.0.1:9090
2020-10-20 22:33:29,933::INFO::[_cplogging:213] [20/Oct/2020:22:33:29] ENGINE Bus STARTING
2020-10-20 22:33:30,084::INFO::[_cplogging:213] [20/Oct/2020:22:33:30] ENGINE Serving on https://127.0.0.1:9090
2020-10-20 22:33:30,186::INFO::[_cplogging:213] [20/Oct/2020:22:33:30] ENGINE Serving on http://127.0.0.1:8095
2020-10-20 22:33:30,187::INFO::[_cplogging:213] [20/Oct/2020:22:33:30] ENGINE Bus STARTED
2020-10-20 22:33:30,188::INFO::[SABnzbd:1458] Starting SABnzbd.py-3.1.0
2020-10-20 22:33:30,192::INFO::[dirscanner:117] Dirscanner starting up
2020-10-20 22:33:30,195::INFO::[urlgrabber:96] URLGrabber starting up
2020-10-20 22:33:30,197::INFO::[notifier:122] Sending notification: SABnzbd - SABnzbd 3.1.0 started (type=startup, job_cat=None)
2020-10-20 22:33:30,203::INFO::[postproc:232] Completed Download Folder /home/zlatko/mnt/nas/_/Downloads is not on FAT
2020-10-20 22:33:30,491::INFO::[notifier:182] Send to NotifyOSD: SABnzbd / SABnzbd 3.1.0 started

Please let me know if you need any additional information.

Thanks,
Thomas

[sander]

if you set SAB's logging to +Debug (under the Wrench symbol), your sabnzbd.log will tell in detail what SAB does and doesn't

[ZlatkO]

Okay, I'll do that and wait for the next "ENCRYPTED" pause to happen. Thanks!

[ZlatkO]

Okay, well that didn't take long, did it? I would have posted the logs here, but as it seems I can't because of:

The submitted form was invalid. Try submitting again.
Your message contains 99904 characters.
The maximum number of allowed characters is 20000.

So instead I'll put it up on pastebin.com and post the links here. Here we go;

This is the full log from the initial download attempt: https://pastebin.com/CdCniYuC
There were another few entries while the download was paused: https://pastebin.com/tL3SjX4G
And this is after I simply clicked "Continue" without doing anything else: https://pastebin.com/E8MQcgve

And that was that, the NZB was fully downloaded and decrypted without any further input from my side (except for clicking "Continue/Resume", of course). Does any of this explain why it pauses the download as "ENCRYPTED"?

[sander]

Did you read the log yourselves? What did you see?

Reason: at passwords, I'm just a user, and in your first log, I see a few "Trying password" (2 from the NZB, 4 or so from password.ini), and that fails. I see no password trying in the other log files ...

[ZlatkO]

Did you read the log yourselves? What did you see?

Reason: at passwords, I'm just a user, and in your first log, I see a few "Trying password" (2 from the NZB, 4 or so from password.ini), and that fails. I see no password trying in the other log files ...

Ummm ... why, yes, of course I did. And what I did not see is any reason to go looking for passwords in passwords.ini, because the password was already supplied in the URL, and was detected and extracted by SABnzbd just fine, as stated in the logs:

Code: Select all

2020-10-24 20:58:46,138::DEBUG::[nzbstuff:1890] Saving attributes {'cat': '*', 'pp': 3, 'script': 'None', 'priority': 0, 'final_name': 'Die.Vulkan.Haie.von.La.Reunion.GERMAN.DOKU.HDTVRip.x264-TMSF', 'password': 'ygVcSHJD0KHaRdQ0BxxQHN0XsTylEJ8F7z8LxT3', 'url': 'Die.Vulkan.Haie.von.La.Reunion.GERMAN.DOKU.HDTVRip.x264-TMSF{{ygVcSHJD0KHaRdQ0BxxQHN0XsTylEJ8F7z8LxT3}}.nzb'} for Die.Vulkan.Haie.von.La.Reunion.GERMAN.DO KU.HDTVRip.x264-TMSF

And I already did mention several times in both my original report and my followup containing the logs that I do not have to change or reenter the password once the download gets stopped, and it still gets completed and decrypted properly once I click "Resume". So this suggests to me that a missing or wrong password is not the problem here.

Or did I misunderstand what you were trying to point me at?

[sander]

Sorry, I don't understand what you mean.

[ZlatkO]

Oooh, I think I misread your reply ... sorry! So you're saying that there's an indication in the logs somewhere that also the password from the NZB itself failed, ie. the one that's encoded within the curly brackets {{...}} in the filename? I guess I must have missed that one. I'm going back to re-read the logs.

But even if that*s the case, the question remains: why does it fail to decrypt with the NZB-supplied password on the first try, and succeeds to decrypt the very same NZB with the very same password on the second try (ie. after I hit "Resume)?

[ZlatkO]

Yes, you're right, now I see what you mean: in lines 246 - 250 from the first log it collects a total of 8 passwords (1 "user supplied" + 2 "from nzb metadata" + 5 "from passwords.ini", and then later on in line 267 it builds what looks like a 100% correct commandline for unpacking (including the correct password), but still claims that it didn't work out in line 283.

Which is no big wonder, actually, as (if I read the logs correctly) it only has the first 3 of 7 RARs downloaded at this time so far ... could it be that this is related to me having "[x] Direct Unpack" enabled? The description of this option warns that it "Only works for jobs that do not need repair.", but from the third log in lines 167 - 174 it seems that repair was actually not needed here, so it should have succeeded ... or am I missing something?

[safihre]

Do you maybe have the original NZB for me?
This could be a bug in the rarfile module that we use, because it says:

Code: Select all

2020-10-24 20:58:54,343::INFO::[assembler:317] Trying password "ygVcSHJD0KHaRdQ0BxxQHN0XsTylEJ8F7z8LxT3" on job "Die.Vulkan.Haie.von.La.Reunion.GERMAN.DOKU.HDTVRip.x264-TMSF"

Which I assume is the correct password since it was part of the NZB filename, however it is not detected as such.

[ZlatkO]

Sure, no problem, here's the link. But it probably won't help much, because the problem doesn't seem to be reproducible. Just for kicks, I re-downloaded it again just now, and it worked fine on the first try this time.

I also noticed that I had "Action when encrypted RAR is downloaded: Pause" configured, could that maybe conflict with "[x] Direct Unpack"? I have now changed it to "Action when encrypted RAR is downloaded: Off" just to see if that makes a difference.

[safihre]

No I think it is more of a fundamental problem with rarfile module, which I know can be unreliable sometimes. Just need to make it a bit more robust Direct unpack is a bit blunt, it just goes ahead and tries to unpack with the first password it can find. It doesn't care about that other detection that pauses it
But indeed if you switch encrypted detection off, it disables any checking behavior.

[SABfaninAus]

Hi there,

Just a quick note that I'm still experiencing this behaviour. Today, I added 10 password NZBs, each with a correctly supplied password (manually entered).

8 of the NZBs downloaded without issue. 2 were paused with the error:

"Paused job "<filename>" because of encrypted RAR file (if supplied, all passwords were tried)"

Just as in ZlatkO's post, clicking "Play/Continue" causes the these files to continue downloading and unrar successfully - no additional password is supplied.

I'm running version 3.1.0 [23f86e9] on a Synology NAS as 3.1.1 is not yet available.

I'm also using Direct unpack, which has never failed in this way throughout all of my many years using SABnzbd.

Is this bug fixed in v3.1.1 or is it still in progress?

Thanks,

SABfaninAus

[safihre]

There's no specific fix, because we don't make the rar-analyzer. For some reason it is not working well on these files and crashing out.
I don't have good solution for it at the moment, except to disable Encryption check.

[SABfaninAus]

Hey safihre,
Thanks for letting me know. It's not a huge issue as hitting "Play/Continue" always completes the download. Strange that it only happens intermittently.
Thanks,
SABfaninAus
PS: I note v3.1.1 [99b5a00] was just pushed out to the SynoCommunity.