PAR2 Files Disappearing During Download if Post-Processing Is Enabled [SOLVED]

[bob511]

Trying to run down whatever's causing the PAR2 files queued as part of an NZB to vanish on their way to their Incomplete subfolder, resulting in a CRC failure when trying to unpack a damaged download.

When no post-processing option is specified, the par2 files seem to download normally.
When any sort of post-processing is specified (from R to D+Script), the par2 files "download" at an unrealistic rate, and only the smallest par2 actually makes it to the download's folder in Incomplete.  All other files seem to download normally, and if none of them are incomplete/need repair, the unpack stage goes off without a hitch.
Doesn't seem to be a newsserver/retention issue, since the same par2 files download in the one case but not the other.

Running version 0.3.1rc1 on Linux (also observed the issue with 0.3.0).  Cleared out my sabnzbd.ini and the problem persists.


An Example

---

A download's queue (before any downloading has started)

Code: Select all

selection:all  none  invert
	Filename/Subject	Size	Age
	Download.In.Question-.vol000+01.PAR2 	2.43 MB 	97 days, 7:12:48
	Download.In.Question-.vol001+02.PAR2 	4.86 MB 	97 days, 7:12:39
	Download.In.Question-.vol003+03.PAR2 	7.21 MB 	97 days, 7:12:11
	Download.In.Question-.vol006+05.PAR2 	11.99 MB 	97 days, 7:11:32
	Download.In.Question-.vol011+08.PAR2 	19.12 MB 	97 days, 7:11:00
	Download.In.Question-.vol019+15.PAR2 	35.57 MB 	97 days, 7:10:18
	Download.In.Question-.vol034+30.PAR2 	70.91 MB 	97 days, 7:09:09
	Download.In.Question-.vol064+42.PAR2 	99.19 MB 	97 days, 7:06:44
	Download.In.Question-.vol106+42.PAR2 	99.19 MB 	97 days, 7:06:11
	Download.In.Question.Sample-.vol00+1.PAR2 	0.53 MB 	97 days, 6:56:45
	Download.In.Question.Sample-.vol01+2.PAR2 	1.06 MB 	97 days, 6:56:42
	Download.In.Question.Sample-.vol03+3.PAR2 	1.59 MB 	97 days, 6:56:38
	Download.In.Question.Sample-.vol06+5.PAR2 	2.64 MB 	97 days, 6:56:28
	Download.In.Question.Sample-.vol11+9.PAR2 	4.75 MB 	97 days, 6:56:10
	Download.In.Question-.md5 	0.00 MB 	97 days, 11:43:32
	Download.In.Question-.nfo 	0.01 MB 	97 days, 11:43:32
	Download.In.Question-.par2 	0.08 MB 	97 days, 11:43:31
	Download.In.Question.nzb 	4.49 MB 	97 days, 11:43:30
	Download.In.Question-.part01.rar 	98.71 MB 	97 days, 11:26:38
	Download.In.Question-.part02.rar 	98.72 MB 	97 days, 11:26:36
[...etc...]
	Download.In.Question-.sfv 	0.01 MB 	97 days, 7:12:53
	Download.In.Question.Sample- 	105.22 MB 	97 days, 7:02:06
	Download.In.Question.Sample-.par2 	0.01 MB 	97 days, 6:56:47

With no post-processing, the download's Incomplete subfolder after a bit of downloading:

Code: Select all

 Directory of R:\path\to\SABnzbdplus\downloads\incomplete\Download In Question.nopp

02/14/2008  12:33 AM    <DIR>          .
02/14/2008  12:48 AM    <DIR>          ..
02/14/2008  12:31 AM         7,300,044 Download.In.Question-.vol003+03.PAR2
02/14/2008  12:33 AM        12,140,540 Download.In.Question-.vol006+05.PAR2
02/14/2008  12:30 AM         2,459,548 Download.In.Question-.vol000+01.PAR2
               3 File(s)     21,900,132 bytes
               2 Dir(s)  22,629,858,304 bytes free

After re-loading the same queue, with +R, after a bit of downloading again:

Code: Select all

 Directory of R:\path\to\SABnzbdplus\downloads\incomplete\Download In Question

02/14/2008  12:34 AM    <DIR>          .
02/14/2008  12:48 AM    <DIR>          ..
02/14/2008  12:34 AM           537,412 Download.In.Question.Sample-.vol00+1.PAR2
02/14/2008  12:34 AM                85 Download.In.Question-.md5
02/14/2008  12:34 AM             6,415 Download.In.Question-.nfo
02/14/2008  12:34 AM            78,524 Download.In.Question-.par2
02/14/2008  12:34 AM         2,459,548 Download.In.Question-.vol000+01.PAR2
02/14/2008  12:34 AM         4,624,113 Download.In.Question.nzb
               6 File(s)      7,706,097 bytes
               2 Dir(s)  22,629,857,280 bytes free

While the download without post-processing proceeds through the par2 files like it should, the +R download grabs the first par2, an additional par2, and the first par2 for the sample (and then the next few small files before I paused the download).  The rest of the par2 files disappear.

---

Attaching snippets of sabnzbd.log during the download with post-processing, and without.  Also attaching my sabnzbd.ini.

Hopefully I'm just missing something obvious.

[shypike]

The PAR2 file are supposed to vanish from the queue.
As soon as basic PAR2 info is collected (the smallest of the VOLxx+yyy.par2 files is in), the other PAR2 files are removed from the queue.
They re-enter the queue when the PAR2-verification fails and will get downloaded after all.
After that PAR2 repair is done.

The mechanism works by determining the amount of repair blocks still available in the queue, this depends on the correct naming of the PAR2 files.
The mechanism only fails when there are not enough remaining PAR2 files to be able to repair. SABnzbd does not download more PAR2 files if it knows beforehand that repair will not be possible.
However, any complex method can contain errors, so there may be a problem with SABnzbd.
Most of the time, its really a download that has too many missing parts.
We even had one situation with a download at the edge of retention time, where the server would intermittently had and did not have articles, completely unpredictable.

Does this problem only happen with this particular NZB or does it happen more?
Can you email the troublesome NZB file to [email protected] ?
Can you email a ZIP file with all the logging files to the same address?

[bob511]

Does not seem to be NZB-specific, no; it happens frequently with NZBs for files both new and old.  In fact, looking over my history since I cleared it ten days back, I don't see a single successful repair, or even a sign that a repair was initiated; either things go smoothly, or CRC fails (or in a couple of cases one of the rars is missing, but that's probably just an incomplete NZB).

Hmm.  If the removal of the pars is intended behavior with post-processing enabled, then I suppose the issue must be elsewhere.

A download that fails CRC during the unpack stage invariably ends up with only those couple of par2 files alongside it when moved to Complete, and it can always be repaired by separately redownloading the par2 set (without post-processing, obviously) and repairing manually with QuickPar; these are almost never heavily damaged posts, but typically just a few missing blocks (for which the smallest par2 is obviously still insufficient).  So it seems the posted pars included in the NZBs are clearly sufficient for repair, but maybe not being pulled back in for some reason, and so SABnzbd+ spits out something like

Code: Select all

2008-02-13 01:53:52,695::INFO::[assembler] Starting PostProcessing on msgid_xxxx SomeDownload.nzb => Repair:True, Unpack:True, Delete:True, Script:False
2008-02-13 01:53:52,695::INFO::[assembler] Par2 check starting on msgid_xxxxx SomeDownload.nzb
2008-02-13 01:53:52,696::INFO::[assembler] Running repair on set somedownload
2008-02-13 01:53:52,712::INFO::[nzbstuff] Finishing import on Some.Unrelated.Download-[098/112] "some.unrelated.download.vol000+01.PAR2" yEnc (1/6)
2008-02-13 01:53:52,713::INFO::[sabnzbd] Loading data for SABnzbd_nzf_TSe0ER from /path/to/SABnzbd/Incomplete/cache/SABnzbd_nzf_TSe0ER
2008-02-13 01:53:52,762::INFO::[newsunpack] Par verify failed on /path/to/SABnzbd/Incomplete/cache/Movies/SomeDownload/somedownload.vol0+1.PAR2!
2008-02-13 01:53:52,763::INFO::[assembler] Par2 check finished on msgid_xxxx SomeDownload.nzb

I guess I can shoot a full log over that includes some start-to-finish downloads that exhibit this problem.

EDIT: Ok, logs sent.

EDIT 2: Hmm, on a closer look at the logs that might not be the absolute best example, since looking at the history the par2 file SABnzbd tried to use was for the sample and not the post proper.  Unfortunately, given the file sizes, that seems to be the only example I have complete start-to-finish logging for.  I suppose I can clear out my logs and run a fresh download.

[shypike]

Received your logs, but it's not enough. I need also sabnzbd.log (which is the most recent one) and please also the NZB.
Otherwise it's very difficult to diagnose.
Do you use the article_cache ? If so, what size is it?

Also, which Linux do you use?

[bob511]

I was trying to narrow the download session down to a single failed download, so you wouldn't have to hunt through logs of unrelated stuff, but I'll clear out the logs and run a sample download that I'm pretty sure will fail.

Running ClarkConnect 4.2 (an RHEL4 derivative), kernel's 2.6.18-8.1.14.3.cc, Python 2.5.1, Cherrypy 2.2.1, Cheetah 2.0rc8, par2cmdline 0.4, and of course SABnzbd+ 0.3.1rc1 (guess I'll try the final release after this test finishes).

Article cache is at 0 (saw that thread from back when about repairing/unpacking issues when using the cache).

Looks like the fresh test run finished, though I had it set on Repair instead of Unpack/Delete, so you'll have to take my word that a subsequent Quickpar run shows .r30 a block short of complete (and even would be able to repair it in this case, were I to let it use the one par2 that stuck around, since the damage is so slight--but SABnzbd still should have caught that itself, right?).  I'll send the full logs set and the NZB over your way.

Stuff's sent.  Thanks for your time and attention.

[bob511]

Looking through the logs some more, it does seem awfully similar to the PAR problem you're dealing with in the other thread; inevitably there's a "::INFO::[newsunpack] Par verify failed on /path/to/SABnzbd/Incomplete/File/file.vol000+01.PAR2!" message in there, but no further par2s are fetched (and even in the case where that one little par2 is enough to fix things, no repair is run anyway).

Something I should've thought of earlier is trying to run par2cmdline manually, instead of Quickpar, in case the latter is doing a more thorough job for some reason.  I guess I'll try that in a couple of hours.

[shypike]

Bob,

I don't have much time this weekend, but I am taking your complaint seriously.
At least this time, I may have some useful material on this elusive problem.
BTW: SABnzbd uses par2cmdline to do verification and repairs.

I doubt if the Final release (out now) will make a difference.

[shypike]

What I see in the log is that SABnzbd does not try to download additional PAR2 files after the first verify failed.
It does this when it estimates that there would not be enough par2 files left in the queue to repair.
Mind you: the files are not lost, they have not been downloaded yet (by design).
In this case it looks like SAB takes the wrong decision. Problem is, I cannot see why it draws this conclusion.
It's quite suspicous, because normally one or two INFO lines are logged when par2cmdline does its work.
You would see either "all files correct", "repair is required" or something along those lines.
Now nothing at all is logged (except the final conclusion), which is very odd.

What is the exact output of par2cmdline if you run it manually on the (incomplete) set that has been downloaded?
Maybe that way I can see what's going on (possibly an incompatibility between SABnzbd and par2cmdline).

[bob511]

[user]# par2verify file.vol000+01.PAR2
par2cmdline version 0.4, Copyright (C) 2003 Peter Brian Clements.

par2cmdline comes with ABSOLUTELY NO WARRANTY.

This is free software, and you are welcome to redistribute it and/or modify
it under the terms of the GNU General Public License as published by the
Free Software Foundation; either version 2 of the License, or (at your
option) any later version. See COPYING for details.

Loading "files.vol000+01.PAR2".
Loaded 193 new packets including 1 recovery blocks

There are 95 recoverable files and 0 other files.
The block size used was 2272728 bytes.
There are a total of 2067 data blocks.
The total size of the data files is 4695412241 bytes.

Verifying source files:

Target: "file.r00" - found.
[...etc...]
Target: "file.r29" - found.
Target: "file.r30" - damaged. Found 21 of 22 data blocks.
Target: "file.r31" - found.
[...etc...]
Target: "file.rar" - found.
Target: "file.sfv" - found.

Scanning extra files:


Repair is required.
1 file(s) exist but are damaged.
94 file(s) are ok.
You have 2066 out of 2067 data blocks available.
You have 1 recovery blocks available.
Repair is possible.
1 recovery blocks will be used to repair.
[user]#

[shypike]

Output of par2cmdline looks OK to me, exactly what is to be expected.
This is going to be a difficult problem to solve.
So first some questions:

- Does it go wrong for every download?
- Does it go wrong for every download that has par2 errors?
- Which ClarkConnect 4.2 do you use (Commercial, Enterprise, Office)?
- Where did you get the modules from (par2, yenc, cherry etc).
    Especially par2cmdlin. Are these part of the distribution, or apt-get stuff?
    or did you find an tweak them yourself?

[bob511]

- Does it go wrong for every download?
- Does it go wrong for every download that has par2 errors?

Many downloads unpack without issue; however, my history (sitting at around 388GB worth) does not show a single instance where a repair explicitly took place (simply the [PAR-INFO] "scanning" statement for every download), which suggests to me that the downloads that unpack successfully do so because they are undamaged in the first place.

- Which ClarkConnect 4.2 do you use (Commercial, Enterprise, Office)?

Community Edition--what am I, made of money?   

- Where did you get the modules from (par2, yenc, cherry etc).
    Especially par2cmdlin. Are these part of the distribution, or apt-get stuff?
    or did you find an tweak them yourself?

Self-compiled, without tweaks, from the respective project-provided sources (the CC repos are not the most comprehensive); however, all the compiled binaries are the same ones I used with previous/vanilla versions of SABnzbd with no problems repairing that I recall.  I suppose my next step should be setting back up a pre-plus version to make sure my memory isn't failing on that count.

[bob511]

I suppose my next step should be setting back up a pre-plus version to make sure my memory isn't failing on that count.

Three hours later, and for that same download

2008-02-17 08:54:55 File.nzb True


Stage Par2
    [PAR-INFO] smallerfile.mkv: => Verified in 3.8s, all files correct
    [PAR-INFO] file: => Repaired in 90.4s
    [DEL-INFO] smallerfile.mkv: => Deleted 2 file(s)
    [DEL-INFO] file => Deleted 3 file(s)



Stage Unrar
    [RAR-INFO] file: => Unpacked 1 file(s) in 204.6s

A difficult problem to solve, indeed.

[shypike]

I'm working on getting a VMWare'ed ClarkConnect up.
It will take some time and then I have to do some test runs.
Don't expect results for a couple of days...

But I'm determined to get a handle on this problem.

I may contact you before, if I cannot get all the required modules installed 

[bob511]

I'm going to feel like such an ass when you go through this heroic effort and it turns out to be some dumb, piddling oversight on my part. 

I'm still struck by how--at least superficially--similar my issue seems to the guy's over in the "CRC Failed" thread, with the whole "par verify failed but nothing's done about it" pattern--but of course he's running XP SP2.

[shypike]

Almost done setting up ClarkConnect.
But how the hell did you get Python 2.5.1 installed?
The latest RPM  is for Python2.3, not exactly a cutting-edge crowd these RedHatters....
Ubuntu is a lot more SABnzbd-friendly.

How did you compile Python2.5.1?
Mine bails out with:
Compiling /usr/local/lib/python2.5/xmllib.py ...
Compiling /usr/local/lib/python2.5/xmlrpclib.py ...
Compiling /usr/local/lib/python2.5/zipfile.py ...
make: *** [libinstall] Error 1

Very helpful, isn't it...