failed message received right after success message.

[sander]

Code: Select all

2016-10-26 16:59:14,444::DEBUG::[postproc:723] MyDebug:  wdir is /av/new/movies
2016-10-26 16:59:14,445::DEBUG::[postproc:724] MyDebug:  filename is blar.idx
2016-10-26 16:59:14,445::DEBUG::[postproc:723] MyDebug:  wdir is /av/new/movies
2016-10-26 16:59:14,445::DEBUG::[postproc:724] MyDebug:  filename is How to bla (2014).mkv
2016-10-26 16:59:14,445::DEBUG::[postproc:723] MyDebug:  wdir is /av/new/movies
2016-10-26 16:59:14,446::DEBUG::[postproc:724] MyDebug:  filename is 3� (bla y bla).part1.rar

(Ah, there is the offending charachter: a 1/2, just like the 0xbd told us)



So each time SABnzbd is parsing /av/new/movies. I don't understand that either, and I don't understand how safihre's comment can be the explanation. But Safihre is a clever man, so maybe I need some time ... ;-)

Looking at postproc.py:

Code: Select all

        # Cleanup again, including NZB files
        if all_ok:
            cleanup_list(workdir_complete, False)

and

Code: Select all

def cleanup_list(wdir, skip_nzb):
    """ Remove all files whose extension matches the cleanup list,
        optionally ignoring the nzb extension
    """
    if cfg.cleanup_list():

So you have things defined in your cleanup list, right? (Just checking that I read the SAB code correctly)

My hypothesis: workdir_complete should point specifically to the workdir of the specifc download (and that should be cleaned up), not to a general directory. I would say there is a difference between workdir and workdir_complete. But not in your case ... ? Something goes wrong in an assignment? A brute force analysis of the assignment:

Code: Select all

$ cat sabnzbd/postproc.py | grep "workdir_complete ="
    workdir_complete = ''
        tmp_workdir_complete = None
        workdir_complete = workdir
                workdir_complete = create_dirs(complete_dir)
                workdir_complete = get_unique_path(os.path.join(complete_dir, dirname), create_dir=True)
                tmp_workdir_complete = prefix(workdir_complete, '_UNPACK_')
                tmp_workdir_complete = workdir_complete
                    workdir_complete = tmp_workdir_complete.replace('_UNPACK_', '_FAILED_')
                    workdir_complete = get_unique_path(workdir_complete, n=0, create_dir=False)
                    workdir_complete = workdir_complete
        workdir_complete = one_file_or_folder(workdir_complete)
        workdir_complete = os.path.normpath(workdir_complete)

(Wow: "workdir_complete = workdir_complete" ... what could be the reason for that?)

My guess is we should find the cause there.

EDIT:

This is supporting my hypothesis:

Something set in my cleanup list, two seperate downloads, with logging of the wdir:

Code: Select all

$ cat sabnzbd.log | grep -i mydebug | grep wdir

2016-10-27 08:10:22,196::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,202::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,204::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,206::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,207::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,208::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,208::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,209::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_very importand download
2016-10-27 08:10:22,215::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/very importand download
2016-10-27 08:10:22,216::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/very importand download
2016-10-27 08:10:22,218::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/very importand download
2016-10-27 08:10:22,219::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/very importand download
2016-10-27 08:10:40,889::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,891::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,892::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,895::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,897::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,899::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,900::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,901::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/_UNPACK_something I want
2016-10-27 08:10:40,904::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/something I want
2016-10-27 08:10:40,905::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/something I want
2016-10-27 08:10:40,906::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/something I want
2016-10-27 08:10:40,907::DEBUG::[postproc:737] MyDebug:  wdir is /home/sander/Downloads/complete/something I want

So in my case wdir is specific; it's pointing only to the directory of the specific download. And SAB is only parsing that directory.

Now we have to find out why that does not happen on your system...

[sander]

@diamaunt: homework for you, to narrow things down:

Does the error only happen when it's a movie? (You said that earlier, but I'm not sure)
Does the error go away when you have nothing in your SAB cleanup list setting? (I guess so)

[diamaunt]

@diamaunt: homework for you, to narrow things down:

Does the error only happen when it's a movie? (You said that earlier, but I'm not sure)
Does the error go away when you have nothing in your SAB cleanup list setting? (I guess so)

I'll have to recover the offending file from a backup and do some testing.

if I downloaded to a destination that was different, I didn't have the error.

[diamaunt]

@diamaunt: homework for you, to narrow things down:

Does the error only happen when it's a movie? (You said that earlier, but I'm not sure)
Does the error go away when you have nothing in your SAB cleanup list setting? (I guess so)

I recovered the 8 1/2 file, and download a non-movie into the movies category, post processing aborted.
I removed the unwanted extensions from the postprocessing config, no abort.

I moved the 8* file to a non-movie category destination, and downloaded to there, no abort was logged.
I replace the unwanted extensions, and no abort was logged when not in the movie category.

so, for me, I've only seen the abort when there's unwanted extensions listed in post processing, and the category is movie, and there's a file in the directory with a character in the name that sab doesn''t like.

[sander]

so, for me, I've only seen the abort when there's unwanted extensions listed in post processing, and the category is movie, and there's a file in the directory with a character in the name that sab doesn''t like.

Indeed, it seems like it.

You could check out the wordir / wdir debug logging for other downloads, as it should point the specific directory. If you can confirm that, we're closer to the cause.

I still can't reproduce it, you know the cause & workaround (remvoing the strange-character file), so I think I won't dive furhter into this.