Direct Unpack fails immediately

[Kenjiro-dono]

Hey,

a few days ago I upgraded to sabnzbd v3.4.2 (from ~ 3.2, installed from AUR) and I noticed that my direct unpack does not seem to work anymore - at least in a lot of cases. I tried to reproduce and it can be seen by downloading the 10 GB test download. I can see that the direct unpack starts late-ish, I would say after around ~1,5 GB / 3 files are downloaded) and stops immediately afterwards (unpack_ folder is being removed).

1. Can you confirm that direct unpack is working with the 10 GB test download?
2. Can you help me diagnose why it is no longer working on my machine? Debug logging?

On my living room PC I am using Manjaro (/w newest updates), download + unpack to the same HDD (now download to SSD and extraction to HDD), Ryzen 4650G, 16 GB RAM and sufficient space on SSD and HDD. Sabnzbd installed (and probably uses) unrar v6.10 Beta 2.

Regards

[sander]

I tried, I got this with the 10GB test download:

Code: Select all

2021-12-12 21:04:25,295::INFO::[directunpacker:310] DirectUnpacked volume 101 for sometestfile
2021-12-12 21:04:25,351::INFO::[directunpacker:219] Error in DirectUnpack of sometestfile: Unexpected end of archive
2021-12-12 21:04:25,351::INFO::[directunpacker:444] Aborting DirectUnpack for sometestfile

Same as you?

Let me check with another 10GB reference download. BRB

[sander]

I created a fresh post, 10GB total, 103 rar files, a few par files ... same error.

So, what could that be? Too many rar files? ... ? EDIT: tried with 50 rars files of 200MB ... same error.

So, at OP, do you see a pattern? Possible cause?

Normally I have no DirectUnpack on, so my sabnzbd.log does not report any other "Error in DirectUnpac" occurences.

Code: Select all

2021-12-12 22:43:21,856::INFO::[notifier:123] Sending notification: Post-processing - reftestnzb_10GB_e1fbcefff737 (type=pp, job_cat=*)
2021-12-12 22:43:21,858::INFO::[directunpacker:310] DirectUnpacked volume 101 for my_file_10GB
2021-12-12 22:43:21,858::INFO::[postproc:730] Starting verification and repair of reftestnzb_10GB_e1fbcefff737
2021-12-12 22:43:21,886::INFO::[__init__:919] [sabnzbd.postproc.parring] /media/zeegat/incomplete/reftestnzb_10GB_e1fbcefff737/__ADMIN__/__verified__ missing
2021-12-12 22:43:21,886::INFO::[postproc:750] Running verification and repair on set the_10GB
2021-12-12 22:43:21,922::INFO::[directunpacker:219] Error in DirectUnpack of my_file_10GB: Unexpected end of archive
2021-12-12 22:43:21,922::INFO::[directunpacker:444] Aborting DirectUnpack for my_file_10GB
2021-12-12 22:43:21,937::DEBUG::[newsunpack:2016] Quick-check of file my_file_10GB.part045.rar OK
2021-12-12 22:43:21,938::DEBUG::[newsunpack:2016] Quick-check of file my_file_10GB.part063.rar OK

[sander]

Ah, "great": also the "Error in DirectUnpack" in the 100MB test download. And the 10GB test download now went without error. So it's intermittent.

Code: Select all

2021-12-13 14:06:52,112::INFO::[newsunpack:258] Unrar starting on /home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB
2021-12-13 14:06:52,112::DEBUG::[newsunpack:483] Rar_sets: {'sometestfile-100MB': ['/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part5.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part1.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part6.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part3.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part2.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part4.rar', '/home/sander/.sabnzbd/Downloads/incomplete/test_download_100MB/sometestfile-100MB.part7.rar']}
2021-12-13 14:06:52,112::DEBUG::[newsunpack:501] DirectUnpacker still alive for test_download_100MB: 05/07
2021-12-13 14:06:52,192::INFO::[directunpacker:310] DirectUnpacked volume 6 for sometestfile-100MB
2021-12-13 14:06:52,193::INFO::[directunpacker:219] Error in DirectUnpack of sometestfile-100MB: Unexpected end of archive
2021-12-13 14:06:52,194::INFO::[directunpacker:444] Aborting DirectUnpack for sometestfile-100MB
2021-12-13 14:06:52,595::DEBUG::[filesystem:1001] Removing dir recursively /home/sander/.sabnzbd/Downloads/complete/_UNPACK_test_download_100MB.2
2021-12-13 14:06:53,040::DEBUG::[downloader:938] Thread 3@newsreader.eweka.nl: forcing disconnect
2021-12-13 14:06:53,053::DEBUG::[downloader:938] Thread 1@newsreader.eweka.nl: forcing disconnect
2021-12-13 14:06:53,071::DEBUG::[downloader:938] Thread 4@newsreader.eweka.nl: forcing disconnect
2021-12-13 14:06:53,084::DEBUG::[downloader:938] Thread 2@newsreader.eweka.nl: forcing disconnect
2021-12-13 14:06:53,094::DEBUG::[downloader:222] Resetting article queue for <Server: newsreader.eweka.nl:563>

10GB test download that went OK:

Code: Select all

Nametest_download_10GB
Completed12 minutes ago
StatusCompleted
Size10.2 GB
CategoryDefault
Path/home/sander/.sabnzbd/Downloads/complete/test_download_10GB.1/test_download_10GB.bin
Sourcehttps://sabnzbd.org/tests/test_download_10GB.nzb
DownloadDownloaded in 6 mins 32 seconds at an average of 26.5 MB/s
Age: 52d
Serversnewsreader.eweka.nl=10.2 GB
Repair[sometestfile] Quick Check OK
Unpack[sometestfile] Direct Unpack - Unpacked 1 files/folders in 9 mins 5 seconds

[Kenjiro-dono]

Hey,

sorry for the late reply. I didn't get notified on new posts.

It is interesting to see, that it might not be consistent. However on my end it seems to be consistent (several tests, all couldn't be direct unpacked).

I was about to ask HOW to activate more detailed logging because I couldn't find anything in any of the configurations. But ... it can be activated next to the test downloads :-). My test:

Code: Select all

2021-12-14 00:14:07,293::INFO::[directunpacker:438] DirectUnpacked volume 1 for sometestfile
2021-12-14 00:14:09,123::INFO::[directunpacker:219] Error in DirectUnpack of sometestfile: Unexpected end of archive
2021-12-14 00:14:09,123::INFO::[directunpacker:444] Aborting DirectUnpack for sometestfile

I tried another download. Direct Unpack failed as above however it is clear that the download itself is okay:

Code: Select all

2021-12-14 00:38:47,037::INFO::[postproc:752] Running verification and repair on set sometestfile
2021-12-14 00:38:47,040::INFO::[newsunpack:1108] Quick-check for sometestfile is OK, skipping repair
2021-12-14 00:38:47,042::INFO::[postproc:807] Verification and repair finished for test_download_10GB-1
2021-12-14 00:38:47,079::INFO::[postproc:428] Running unpack_magic on test_download_10GB-1

Debug logging, which I activated as well, don't seem to provide any additional relevant information.

My thoughts? Might be an issue with unrar. Which version are you using? The question is if the file is really damaged or just seems to be damaged for Direct Unpack. Might be an issue with Eweka as I am using this provider as well if the file is really damaged.