Inconsistent Processing Execution

[deepblue]

Hi All - long time user of SAB + Sickbeard. Nary an issue ever - until just recently. For the last several weeks many of my downloads have been producing the "there are no videofiles in folder" error and leaving me with a half processed media download (where temporary folder holding the rars, etc. sits in my final download location vs. being sorted into the correct TV show folder. This issue only seems to be present with Sickbeard induced downloads, hence it's affecting only tv shows. As a point of reference I've got a separate category for Sickbeard downloads called "tv_sb":



Anyhow - I've been getting a strange, inconsistent behaviour where this "there are no videofiles" error pops up (randomly, every few downloads it pops up). I dug through the logs and can see why it's occurring, but can't explain what's causing it. Looks like a bug to me but who knows. The logs show that the downloads in question (that produce this error)) have the Repair, Unpack, Delete flags set to "false", despite my having them set to "Default" which should produce all of those being "true" -- which it does for the successful downloads that use this same category. Here's the log to explain:

http://pastebin.com/wuxEicKw

The critical entry here is:

Code: Select all

2015-11-04 16:32:55,345::INFO::[postproc:283] Starting PostProcessing on Cuffs.1x02.720p.HDTV.x264-FoV => Repair:False, Unpack:False, Delete:False, Script:sabToSickBeard.exe, Cat:tv_sb

I can't for the life of me figure out why these flags are being set this way, as the flags are set correctly on the next download that occurred:

http://pastebin.com/RxWDFDXx

Which as you can see sets the flags correctly:

Code: Select all

2015-11-04 23:33:26,342::INFO::[postproc:283] Starting PostProcessing on American.Horror.Story.S05E05.720p.HDTV.x264-FLEET => Repair:True, Unpack:True, Delete:True, Script:sabToSickBeard.exe, Cat:tv_sb

Any ideas?

Things I've tried:
- Upgrading from 0.7.2 to 0.8.0 (no difference, persists in both stable and beta releases)
- "hard coding" the processing of the "tv_sb" category to +Delete (no difference, same behavior)
- Updating SabtoSickbeard.exe to latest (no difference)

Happy to troubleshoot this further - thanks!

[shypike]

To prevent issues, set the post-processing of category "tv_sb" to "+Delete" instead of "Default".
Either that or SickBeard sends the wrong post-processing setting along with the NZB.

[deepblue]

To prevent issues, set the post-processing of category "tv_sb" to "+Delete" instead of "Default".
Either that or SickBeard sends the wrong post-processing setting along with the NZB.

I've done that before and the issue still happens. Would you happen to know where I can see the post-processing setting that SB sends? I didn't realize it did that.

Thanks.

[deepblue]

Dug out SB logs and all I can see is this (for the post in question that didn't process):

Code: Select all

2015-11-04 16:30:02 INFO     SEARCHQUEUE-RSS-SEARCH :: Sending NZB to SABnzbd: Cuffs.1x02.720p.HDTV.x264-FoV
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: SABnzbd URL: http://192.168.0.10:8080/sabnzbd/api?ma_password=&apikey=**redacted**&name=https%3A%2F%2Fdognzb.cr%2Ffetch%2F**redacted**&cat=tv_sb&priority=1&mode=addurl&ma_username=
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: Result text from SAB: ok
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: NZB sent to SAB successfully

[deepblue]

Just as follow up - I set the category in SAB to +Delete, and had Sickbeard pick up 6 episodes of a random program. The first three processed correctly, and the second three processed "incorrectly" (didn't Repair, Unpack or Delete).

[shypike]

But what does the download history box tell you about why things failed?
(Click on the item in History).

[deepblue]

But what does the download history box tell you about why things failed?
(Click on the item in History).

MORE:

Code: Select all

The.Good.Wife.S06E10.The.Trial.1080p.WEB-DL.DD5.1.H.264-CTRLHD

Loading config from E:\NZB\SAB\scripts\autoProcessTV.cfg
Opening URL: http://192.168.0.10:8081/home/postprocess/processEpisode?nzbName=The.Good.Wife.S06E10.The.Trial.1080p.WEB-DL.DD5.1.H.264-CTRLHD.nzb&quiet=1&dir=E%3A%5CVideo%5CTV%5CThe.Good.Wife.S06E10.The.Trial.1080p.WEB-DL.DD5.1.H.264-CTRLHD
Processing folder: E:\Video\TV\The.Good.Wife.S06E10.The.Trial.1080p.WEB-DL.DD5.1.H.264-CTRLHD

There are no videofiles in folder: E:\Video\TV\The.Good.Wife.S06E10.The.Trial.1080p.WEB-DL.DD5.1.H.264-CTRLHD

Compare this to an item added the same way (via Sickbeard) further up the queue, which looks like this:

Code: Select all

The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD

Loading config from E:\NZB\SAB\scripts\autoProcessTV.cfg
Opening URL: http://192.168.0.10:8081/home/postprocess/processEpisode?nzbName=The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD.nzb&quiet=1&dir=E%3A%5CVideo%5CTV%5CThe.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD
Processing folder: E:\Video\TV\The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD



Processing E:\Video\TV\The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD\150524_14.mkv (The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD.nzb)

Found result in history: (95451, 6, [], 64)

Parsed The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD into The Good Wife - S6E4 - Oppo.Research.1080p.WEB-DL.DD5.1.H.264 (CTRLHD) [ABD: False]

Looking up The Good Wife in the DB

Lookup successful, using tvdb id 95451

Loading show object for tvdb_id 95451

Retrieving episode object for 6x4

Snatch history had a quality in it, using that: 1080p WEB-DL

Sick Beard snatched this episode, marking it safe to replace

This download is marked as safe to replace existing file

Found release name The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD

Destination folder for this episode: E:\Video\TV\The Good Wife\Season 6

Moving file from E:\Video\TV\The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD\150524_14.mkv to E:\Video\TV\The Good Wife\Season 6\The Good Wife - 6x04 - Oppo Research.mkv

Deleted folder: E:\Video\TV\The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD

Processing succeeded for E:\Video\TV\The.Good.Wife.S06E04.Oppo.Research.1080p.WEB-DL.DD5.1.H.264-CTRLHD\150524_14.mkv

If I look at the queue items before they are active - I can clearly see some of the queue items tagged for "Download" vs. a few tagged for "+Delete". The issue seems to be some random element that isn't acknowledging the processing instructions for this category.

[shypike]

What is in the folder created by SABnzbd?
Any file recognisable as a media file?
The error message comes from SickBeard.

[deepblue]

The temporary folder just contains un-repaired, non-unpacked RAR and PAR2 files. I have to manually process and move the files when this happens.

Isn't it clear from what I've shown you here that SAB is picking up the NZB from Sickbeard and not applying the processing instructions consistently? You can see in the log that it sometimes sets the repair/unpack/delete to "true" and sometimes to "false".

[shypike]

OK.
Have you set the category "tv_sb" explicitly to "+Delete" by now?
If that doesn't solve the problem, I don't know what will.
I'm not very familiar with SickBeard, but if you cannot find a post-processing setting it it, it likely has none.
What I don't have is a log that shows the API call that SickBeard uses to get the NZB into SABnzbd.
If that doesn't contain a post-processing value, then it cannot be a SickBeard problem.

[deepblue]

All I have from the Sickbeard logs is this:

Code: Select all

2015-11-04 16:30:02 INFO     SEARCHQUEUE-RSS-SEARCH :: Sending NZB to SABnzbd: Cuffs.1x02.720p.HDTV.x264-FoV
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: SABnzbd URL: http://192.168.0.10:8080/sabnzbd/api?ma_password=&apikey=**redacted**&name=https%3A%2F%2Fdognzb.cr%2Ffetch%2F**redacted**&cat=tv_sb&priority=1&mode=addurl&ma_username=
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: Result text from SAB: ok
2015-11-04 16:30:02 DEBUG    SEARCHQUEUE-RSS-SEARCH :: NZB sent to SAB successfully

That API call appears to have a priority setting and a "mode", but no processing instructions. To answer your first question, yes, I've set the category to +Delete.

This one is a real mystery to me as I've had this configuration for years - the only change I've made it moving to a new server running Windows 10, but the configuration is identical.

[shypike]

OK, we can rule out a problem in SickBeard.
There's one tiny possibility that the indexer sends along a category that overrides tv_sb.
That's so unlikely, I'll ignore that for now.
If it happened, you would see that the item indeed had a different category.

The problem is that I cannot think of any way in which the PP settings would be incorrect.
It's not like we had such complaints before.

Maybe a complete debug log of one failing download would shed more light on this.

In the mean time, you might set up a pre-queue script (see: http://wiki.sabnzbd.org/user-pre-queue-script ).

Code: Select all

@echo off
echo 1
echo.
echo 3

This will force each and every NZB to "+Delete"

[deepblue]

Thanks shypike for helping me troubleshoot this further. I agree with you - you'd think that you'd hear from many more people on this if it were a widespread issue.

When you ask for a complete debug log - can you tell me how I provide that? Is what I provided in the first post not a full debug log http://pastebin.com/wuxEicKw? Please let me know and I'll get on it right away.

I'll use your pre-queue as a workaround also - thanks.

[shypike]

When you ask for a complete debug log - can you tell me how I provide that?

What you posted is just the "info" logging, which is quite limited.
Go to the Status page and select "Debug" instead of "Info".
The rest is the same: get the log file immediately after things go wrong.
BTW: there are 5 logging files, but only the most recent one is downloadable from the Status page.
The rest is in the profile folder (c:\users\USER\AppData\Local\SABnzbd\logs).

[deepblue]

Thanks - I've found what you're talking about, it wasn't showing in the knockstrap skin I am using, I switched to glitter for now and adjusted to +Debug. Restarted SAB and will report back when it occurs again with the log.