Unrar fails

[DoubleU]

I have been using Sabnzbd for a long time now on my NAS and everything was working fine, untill I did an upgrade to 0.4.5.
My previous version was 0.4.2

I'm running this on a NAS, running Debian (Lenny - 2.6.12.6-arm1) on an ARM processor
Unrar version that is installed is UNRAR 3.80 beta 2 freeware.

Now the problem:
Downloads are working fine but the unrar fails.
On the webpage I see the following message: At least one file failed to be unpacked, skipping
I can see the following in the warning screen.

Code: Select all

2008-11-19 21:13:43,868
WARNING
[newsunpack] Missing expected file: filenamel.avi => unrar error?

But if I go to the directory and run manually unrar e filename.rar extracting works just fine.
I restarted the NAS and Sabnzbd and set logging to level 2.
Unfortunately not much information is available in the log.
So any suggestions on what to do?

Code: Select all

2008-11-19 21:13:42,107::INFO::[postproc] Starting PostProcessing on filename.nzb => Repair:True, Unpack:True, Delete:False, Script:None
2008-11-19 21:13:42,111::INFO::[postproc] Par2 check starting on filename.nzb
2008-11-19 21:13:42,115::INFO::[postproc] Running repair on set filename
2008-11-19 21:13:42,140::DEBUG::[newsunpack] build_filelists(): joinables: []
2008-11-19 21:13:42,144::DEBUG::[newsunpack] build_filelists(): zips: []
2008-11-19 21:13:42,148::DEBUG::[newsunpack] build_filelists(): rars: ['/mnt/HD_a2/Usenet/incomplete/filename/filename.rar', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r00', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r01', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r02', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r03', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r04', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r07', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r06', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r05', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r08', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r09', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r10', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r11', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r12', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r13', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r14', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r15', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r16', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r17', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r18', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r19', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r20', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r21', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r22', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r23']
2008-11-19 21:13:42,960::INFO::[newsunpack] Par verify failed on /mnt/HD_a2/Usenet/incomplete/filename/filename.vol00+01.par2!
2008-11-19 21:13:42,964::INFO::[postproc] Par2 check finished on filename.nzb
2008-11-19 21:13:43,013::INFO::[sabnzbd.misc] Creating directories: /mnt/HD_a2/Usenet/complete/TV/filename
2008-11-19 21:13:43,021::INFO::[postproc] Running unpack_magic on filename.nzb
2008-11-19 21:13:43,045::DEBUG::[newsunpack] build_filelists(): joinables: []
2008-11-19 21:13:43,049::DEBUG::[newsunpack] build_filelists(): zips: []
2008-11-19 21:13:43,053::DEBUG::[newsunpack] build_filelists(): rars: ['/mnt/HD_a2/Usenet/incomplete/filename/filename.rar', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r00', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r01', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r02', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r03', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r04', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r07', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r06', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r05', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r08', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r09', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r10', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r11', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r12', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r13', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r14', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r15', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r16', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r17', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r18', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r19', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r20', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r21', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r22', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r23']
2008-11-19 21:13:43,059::INFO::[newsunpack] Unrar starting on /mnt/HD_a2/Usenet/incomplete/filename
2008-11-19 21:13:43,070::DEBUG::Rar_sets: {'filename': ['/mnt/HD_a2/Usenet/incomplete/filename/filename.rar', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r00', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r01', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r02', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r03', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r04', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r07', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r06', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r05', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r08', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r09', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r10', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r11', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r12', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r13', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r14', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r15', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r16', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r17', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r18', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r19', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r20', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r21', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r22', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r23']}
2008-11-19 21:13:43,084::INFO::[newsunpack] Extracting rarfile /mnt/HD_a2/Usenet/incomplete/filename/filename.rar (belonging to filename) to /mnt/HD_a2/Usenet/complete/TV/_UNPACK_filename
2008-11-19 21:13:43,088::DEBUG::[newsunpack] RAR_Extract(): Extractionpath: /mnt/HD_a2/Usenet/complete/TV/_UNPACK_filename
2008-11-19 21:13:43,868::WARNING::[newsunpack] Missing expected file: filename.avi => unrar error?
2008-11-19 21:13:43,874::DEBUG::[newsunpack] rar_unpack(): Rars: ()
2008-11-19 21:13:43,878::DEBUG::[newsunpack] rar_unpack(): Newfiles: ()
2008-11-19 21:13:43,882::INFO::[newsunpack] Unrar finished on /mnt/HD_a2/Usenet/incomplete/filename
2008-11-19 21:13:43,906::DEBUG::[newsunpack] build_filelists(): joinables: []
2008-11-19 21:13:43,910::DEBUG::[newsunpack] build_filelists(): zips: []
2008-11-19 21:13:43,914::DEBUG::[newsunpack] build_filelists(): rars: ['/mnt/HD_a2/Usenet/incomplete/filename/filename.rar', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r00', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r01', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r02', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r03', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r04', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r07', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r06', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r05', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r08', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r09', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r10', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r11', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r12', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r13', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r14', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r15', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r16', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r17', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r18', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r19', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r20', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r21', '/mnt/HD_a2/Usenet/incomplete/filename/filename.r22', '/mnt/HD_a2/Usenet/incomplete/filename/filenamefilename.r23']
2008-11-19 21:13:43,920::INFO::[postproc] unpack_magic finished on filename.nzb

[shypike]

Are there any odd characters in the filename (like accented characters)?
Do all unrar's fail or only for some NZB-s?

Can you email the NZB and the uncensored log file to bugs@sabnzbd.org ?

[DoubleU]

E-mail is on it's way.
About the special characters, I don't have any special characters but all nzb's have a space in the name. like "serie episode.nzb"

[shypike]

On previous releases we have had reports of hanging unrar on some Linux platforms.
This was fixed by modifying the way SABnzbd reads the filenames from the unrar file.
It could be that this leads to other problems on some platforms.

We're very keen on checking whether unpacking has succeeded, because
the next step is to remove the rar files. You'd want to keep the rar files
if unpacking fails.

Thanks for the data. We'll get back to you.
There's probably a fix needed for the 0.4.6 release.

In the mean time, I suggest you go back to release 0.4.4.

PS. One last hunch. I'm using unrar 3.80 (on Ubuntu) and not 3.80Beta2.
Could you try the 3.80 release of unrar?
You can download a Debian compatible binary from RarLabs: http://www.rarlab.com/rar/rarlinux-3.8.0.tar.gz
Just get the unrar program and install it so that it's the first unrar in the path.

[shypike]

I forgot to ask:
Does the unrar done by SABnzbd actually unpack the files?
In other words: is it just a question of a false alert or does the unrar just fail.

Judging from the logging I would say the unrar fails.

[DoubleU]

Thanks for your help so far.
I installed unrar via apt-get in Debian and keep my system up to date. But I will try the other unrar version and see what happens.
I think 3.8 beta is the latest for arm processors.
If that doesn't work I will probably go back to 0.4.4

When SABnzbd is finished I have a directory in my complete directory called _FAILED_Filename
In that directory I can see all the rar files + par2 files if any but no .avi file. So extraction didn't work.
A simple unrar e filename.rar in that directory extracts without any problems.
The incomplete directory is empty.

When I checked the logs to send to you I also noticed that par2 failed, but it wasn't required on that download so I'm not sure if this indicates a simular problem or if that is a standard message when par2repair is not required.

[shypike]

The exact command used for extraction is:

Code: Select all

nice ionice -c2 -n7 unrar x -idp -o- -p- RARFILE FULL_EXTRACT_PATH/

Where RARFILE is the first RAR file.
The nice and ionice parts are only added when these programs are present on the system.

Can you do me a favour and run the above commando from a shell
and email me the exact console output of unrar?
Remove nice and ionice -c2 -n7 if not present.

[DoubleU]

When I enter the full command I get this message:

Code: Select all

ioprio_set: Function not implemented

I then entered the command without ionice -c2 -n7

Code: Select all

nice unrar x -idp -o- -p- ub.0309.notv.part01.rar 

and it extracted the rar just fine.

I also installed 0.4.4 again and this program extracts just fine, this is with the same unrar 3.80 beta. I presume it uses a different extract command then 0.4.5

So it looks like the problem is with ionice on m box.
When I enter only ionice I get the same message "ioprio_get: Function not implemented"
In the man page of ionice I can see the following notes.

Linux supports io scheduling priorities and classes since 2.6.13 with CFQ io scheduler.

And that is probably my problem, I'm running Debian Lenny and using kernel version: 2.6.12.6-arm1

I'll will keep using 0.4.4 for the time being but maybe you can do a check to see if ionice is working, even if it is installed on the system.

[shypike]

I think you found the problem.
The use of ionice was introduced with 0.4.5

I don't think it's SABnzbd's task to check if system utilities work.
If such a utility is installed, it's reasonable to assume it works.
If it doesn't work properly, why not un-install it?

Could you post the help output of ionice?
Mine (Ubuntu server) shows this:

Code: Select all

> ionice -h
Usage: ionice [OPTIONS] [COMMAND [ARG]...]
Sets or gets process io scheduling class and priority.

        -n      Class data (typically 0-7, lower being higher prio)
        -c      Scheduling class
                        1: realtime, 2: best-effort, 3: idle
        -p      Process pid
        -h      This help page

Jens Axboe <axboe@suse.de> (C) 2005

[DoubleU]

You are right, if a util is on a system you would expect it to work

My ionice output.

Code: Select all

Usage: ionice [OPTIONS] [COMMAND [ARG]...]
Sets or gets process io scheduling class and priority.

	-n	Class data (typically 0-7, lower being higher prio)
	-c	Scheduling class
			1: realtime, 2: best-effort, 3: idle
	-p	Process pid
	-h	This help page

Jens Axboe <axboe@suse.de> (C) 2005

I found out that ionice is installed as part of an .deb called linux-utils. So I don't want to un-install that .deb.
I will rename ionice and try 0.4.5 again, I presume that if ionice can't be found by SABnzbd that it will use a different command and extraction will work.
Another option is to update my kernel, but everything else is working fine so I rather go with the easy workaround.

Thanks for your help, at least I know now what is going on and how to correct this.

[shypike]

Looks there's a mismatch between ionice and the system libraries.
ionice reports a missing OS function.

[DoubleU]

It is the kernel.
My kernel doesn't support the IO functions that ionice relies on.

I mentioned that in a previous post.

Linux supports io scheduling priorities and classes since 2.6.13 with CFQ io scheduler.
And that is probably my problem, I'm running Debian Lenny and using kernel version: 2.6.12.6-arm1

I saw your reply in a different thread, it is not ionice that is not working. My kernel doesn't have support for the CFQ scheduler.
No I need to see if I'm going to upgrade my NAS to a different kernel