Delete all Cleanup filetypes from system drive bug in 0.7.14

[hogburto]

Errors I first noticed:

When Type Warning
2013-08-01 17:51:55,779 ERROR: Removing C:\Windows\servicing\TrustedInstaller.exe failed
2013-08-01 17:51:53,161 ERROR: Removing C:\Windows\regedit.exe failed
2013-08-01 17:51:52,772 ERROR: Removing C:\Windows\notepad.exe failed
2013-08-01 17:51:52,766 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\WsatConfig.exe failed
2013-08-01 17:51:52,736 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\vbc.exe failed
2013-08-01 17:51:52,651 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\SMSvcHost.exe failed
2013-08-01 17:51:52,648 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ServiceModelReg.exe failed
2013-08-01 17:51:52,642 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\RegSvcs.exe failed
2013-08-01 17:51:52,640 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\RegAsm.exe failed
2013-08-01 17:51:52,631 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ngentask.exe failed
2013-08-01 17:51:52,630 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ngen.exe failed
2013-08-01 17:51:52,611 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\mscorsvw.exe failed
2013-08-01 17:51:52,559 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\MSBuild.exe failed
2013-08-01 17:51:52,542 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\Microsoft.Workflow.Compiler.exe failed
2013-08-01 17:51:52,512 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\jsc.exe failed
2013-08-01 17:51:52,506 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\InstallUtil.exe failed
2013-08-01 17:51:52,500 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ilasm.exe failed
2013-08-01 17:51:52,490 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\EdmGen.exe failed
2013-08-01 17:51:52,480 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\dfsvc.exe failed
2013-08-01 17:51:52,476 ERROR: Removing C:\Windows\Microsoft.NET\Framework64\v4.0.30319\DataSvcUtil.exe failed

This is incomplete because I ended the task. On a subsequent test, the last file was write.exe even though I don't know if the code goes alphabetically or that's just how files are laid out on a fresh install.

It tried to take out all filetypes matching cfg.cleanup_list (.exe, .nfo, .nzb, .sfv, .srr, .srs, .txt, .url) on C: (the working and complete directories for downloads are both on H: while SABnzbd reports processing status: "Moving: ..." for much longer than usual. I don't run sabnzbd with admin persmissions, but it did clean out those file types from my C:\python27\python.exe directory.

It's running on a fresh Win 8 install with nothing installed to affect SABnzbd (but maybe these could: .NET 3.5, DirectX 9.0c, C++ redistributables x86/x64 '05, '08, '10, & '12), and is running from its Windows executable. SABnzbd has default install and user directory paths on C:. Temporary files are in D:\_temp\sys\ and in D:\_temp\usr\.
The only item of note from the logs is that line 676 in postproc.py is where the action happens. It's easily reproducible and multiple tests are the same with any combination of category or post-processing and with all .nzb's of this type (described below). Removing the filetype Cleanup List prevents the problem.

The only thing unusual about the .nzbs I've noticed cause SABnzbd to act this way is that they only have segments for a single .avi (not a file in segments to be joined in post-proc; a single file as assembled by SABnzbd downloading code) instead of a .rar set or any other files. The download directory for instance looks like H:\_temp\_usenet\5x21 - Slimer Streak.avi\ containing a 5x21 - Slimer Streak.avi and the __ADMIN__ directory upon downloading finish (before moving or post-processing of any kind).

SABnzbd 0.7.14 postproc.py's cleanup_list function seems to either receive a bad wdir or is unable to properly set path under these conditions (I don't know Python).

I hope this is helpful and if you need any info from me, I'll try to get back to you in a timely fashion.

[hogburto]

Additionally, completed downloads are put in H:\_temp\_downloaded\. Neither the download nor the completed directories have and permission restrictions.
Also, I don't know if this happened to C: because it was the system drive, because it's where SABnzbd is installed, or just a quirk of compiled Python.

E: I'll be back Sunday night if the bug does not easily reproduce on other systems and you want any info about my configuration or specific .nzbs.

[shypike]

There might be something weird with your account.
SABnzbd uses a number of profile paths, which might have odd values.
Check the base folders in the Config main page.
The alternative is to set a base path with the -f parameter.

[hogburto]

The config page says C:\Users\[real first name]\Documents and C:\Users\[real first name]\AppData\Local\sabnzbd\admin and all the files there have modify times matching the last time I shut down SAB. Nothing about SAB in My Documents but the scripts folder from before I dropped my old (pre-format) config .ini in the user folder.

Still doing it, but there's some more info, I guess. Since I wanted to be able to test more immediately, I went looking for a smaller file and found VTS_01_4.avi rolling in at a mere 9MB on Binsearch. As probability for an Internet file would have it, it does have a naked woman (demonstrating technical form of a football throw -I kid you not). Here's the thing -no attempt to do file clean-up on C:. It processed fine.

So I go back to one of the files that has produced the bug (5x21 - Slimer Streak.avi) and it still tries to eat my C: drive. I don't know what the significant difference between these should be. Good headers, well-formed XML structure, all segments for 1 file only. Also, when 2 of these files that give problems are in the same NZB, it finishes just fine with no problems.

Anyway, here's the part of the log where things go South. Maybe knowing what SAB was doing right before will help:

2013-08-04 22:42:22,427::INFO::[__init__:893] H:\_temp\_usenet\5x21 - Slimer Streak.avi\__ADMIN__\SABnzbd_nzo_iubo77 removed
2013-08-04 22:42:22,427::INFO::[nzbqueue:211] Saving queue
2013-08-04 22:42:22,427::INFO::[__init__:904] Saving data for queue9.sab in C:\Users\realusername\AppData\Local\sabnzbd\admin\queue9.sab
2013-08-04 22:42:22,430::INFO::[postproc:84] Saving postproc queue
2013-08-04 22:42:22,431::INFO::[__init__:904] Saving data for postproc1.sab in C:\Users\realusername\AppData\Local\sabnzbd\admin\postproc1.sab
2013-08-04 22:42:22,450::INFO::[downloader:241] Waiting for post-processing to finish
2013-08-04 22:42:22,456::INFO::[postproc:278] Starting PostProcessing on 5x21 - Slimer Streak.avi => Repair:True, Unpack:True, Delete:True, Script:None, Cat:*
2013-08-04 22:42:22,457::INFO::[postproc:548] Par2 check starting on 5x21 - Slimer Streak.avi
2013-08-04 22:42:22,457::INFO::[__init__:859] H:\_temp\_usenet\5x21 - Slimer Streak.avi\__ADMIN__\__verified__ missing
2013-08-04 22:42:22,457::INFO::[postproc:581] No par2 sets for 5x21 - Slimer Streak.avi
2013-08-04 22:42:22,461::INFO::[postproc:596] Par2 check finished on 5x21 - Slimer Streak.avi
2013-08-04 22:42:22,634::INFO::[misc:783] Creating directories: \5x21 - Slimer Streak.avi
2013-08-04 22:42:22,654::INFO::[postproc:340] Running unpack_magic on 5x21 - Slimer Streak.avi
2013-08-04 22:42:22,655::INFO::[postproc:342] unpack_magic finished on 5x21 - Slimer Streak.avi
2013-08-04 22:42:25,865::INFO::[postproc:675] Removing unwanted file C:\Program Files\7-Zip\7z.exe
2013-08-04 22:42:25,868::ERROR::[postproc:678] Removing C:\Program Files\7-Zip\7z.exe failed
2013-08-04 22:42:25,868::INFO::[postproc:679] Traceback:
Traceback (most recent call last):
File "sabnzbd\postproc.pyo", line 676, in cleanup_list
WindowsError: [Error 5] Access is denied: 'C:\\Program Files\\7-Zip\\7z.exe'
2013-08-04 22:42:25,871::INFO::[postproc:675] Removing unwanted file C:\Program Files\7-Zip\7zFM.exe
2013-08-04 22:42:25,871::ERROR::[postproc:678] Removing C:\Program Files\7-Zip\7zFM.exe failed
2013-08-04 22:42:25,871::INFO::[postproc:679] Traceback:
Traceback (most recent call last):
File "sabnzbd\postproc.pyo", line 676, in cleanup_list
WindowsError: [Error 5] Access is denied: 'C:\\Program Files\\7-Zip\\7zFM.exe'

(User name altered) Here's the same instance of SAB running with the same settings on a very similar job with no problems:

2013-08-04 22:49:07,105::INFO::[__init__:893] H:\_temp\_usenet\VTS_01_4.avi\__ADMIN__\SABnzbd_nzo_dsgb3n removed
2013-08-04 22:49:07,107::INFO::[nzbqueue:211] Saving queue
2013-08-04 22:49:07,108::INFO::[__init__:904] Saving data for queue9.sab in C:\Users\realusername\AppData\Local\sabnzbd\admin\queue9.sab
2013-08-04 22:49:07,109::INFO::[postproc:84] Saving postproc queue
2013-08-04 22:49:07,111::INFO::[__init__:904] Saving data for postproc1.sab in C:\Users\realusername\AppData\Local\sabnzbd\admin\postproc1.sab
2013-08-04 22:49:07,117::INFO::[downloader:241] Waiting for post-processing to finish
2013-08-04 22:49:07,121::INFO::[postproc:278] Starting PostProcessing on VTS_01_4.avi => Repair:True, Unpack:True, Delete:True, Script:None, Cat:*
2013-08-04 22:49:07,121::INFO::[postproc:548] Par2 check starting on VTS_01_4.avi
2013-08-04 22:49:07,122::INFO::[__init__:859] H:\_temp\_usenet\VTS_01_4.avi\__ADMIN__\__verified__ missing
2013-08-04 22:49:07,122::INFO::[postproc:581] No par2 sets for VTS_01_4.avi
2013-08-04 22:49:07,125::INFO::[postproc:596] Par2 check finished on VTS_01_4.avi
2013-08-04 22:49:07,131::INFO::[misc:783] Creating directories: H:\_temp\_downloaded\VTS_01_4.avi.1
2013-08-04 22:49:07,134::INFO::[postproc:340] Running unpack_magic on VTS_01_4.avi
2013-08-04 22:49:07,135::INFO::[postproc:342] unpack_magic finished on VTS_01_4.avi
2013-08-04 22:49:07,161::INFO::[postproc:521] Cleaning up VTS_01_4.avi (keep_basic=False)
2013-08-04 22:49:07,173::INFO::[postproc:84] Saving postproc queue
2013-08-04 22:49:07,174::INFO::[__init__:904] Saving data for postproc1.sab in C:\Users\realusername\AppData\Local\sabnzbd\admin\postproc1.sab
2013-08-04 22:49:07,177::INFO::[downloader:246] Post-processing finished, resuming download

[shypike]

What do you have in your clean-up list?

[hogburto]

When I first noticed this, it was
.exe, .nfo, .nzb, .sfv, .srr, .srs, .txt, .url
Now it's:
.exe, .htm, .html, .nfo, .nzb, .sfv, .srr, .srs, .txt, .url

It's different because I got rid of the sabnzbd directory in appdata\local and went through the first-run wizard again. All keys, usernames, passwords, directories, and categories set the same; just wanted to see if there was something in the .ini format from an earlier version that might be causing this.
Problem still persists. I mean, when I intentionally tested for it with a known problem file. It's not an everyday problem.

[shypike]

Is there an INI file in SABnzbd's program folder? If so, remove it.

[hogburto]

Nah. No .ini file in the Program Files (x86)\sabnzbd directory.

I've been running SABnzbd in Winpdb with a breakpoint at postproc.py, line 660, cleanup_list
I noticed the local variables there look different between one that works and one that doesn't in the first run through that function:

Code: Select all

file (str):        b'VTS_01_4.avi'
files[0] (list):   [b'VTS_01_4.avi']
path (str):        b'H:\\_temp\\_downloaded\\_UNPACK_VTS_01_4.avi\\VTS_01_4.avi'
skip_nzb (bool):   true
wdir (str):        b'H:\\_temp\\_downloaded\\_UNPACK_VTS_01_4.avi'


file (str):        b'5x21 - Slimer Streak.avi'
files[0] (list):   [b'5x21 - Slimer Streak.avi']
path (str):        b'\\_UNPACK_5x21 - Slimer Streak.avi\\5x21 - Slimer Streak.avi'
skip_nzb (bool):   true
wdir (str):        b'\\_UNPACK_5x21 - Slimer Streak.avi'

Want to catch wdir being set in nzbstuff.py.

[hogburto]

OK, I got it. I can rename any .NZB to the name of one of the broken files, drop it in the blackhole directory, and it will do this.

There is probably a RegEx in TV Sorting trying to find the show name before #x## when none exists and causing a very dangerous clean-up operation and some "where to put the completed directory" shenanigans (My D: drive... not even in the user or system temp paths, just the root of D:). Disabling TV sorting averts this bug.

On the agenda for 0.7.15, then?

[shypike]

Sound like a serious issue.
I'll try to sort this out and I'll get back to you.

[hogburto]

Serious, but very rare. Thank you for your attention.

[shypike]

Are you also using the Sort functions?
And if so, which one and what is the Sort expression?

[hogburto]

The TV sort string I use is:
%sn\%sn - %sx%0e - %en.%ext
With which SAB describes the Processed Result as:
Show Name\Show Name - 1x05 - Episode Name [DTS].avi

Movie sort :
%title (%y)\%title (%y).%ext
Movie Name (2009)\Movie Name (2009) CD1.avi

Date sort:
%t\%t - %y-%0m-%0d - %desc.%ext
Show Name\Show Name - 2009-01-02 -.avi