I’ve seen failed download handling work just fine before. I’ve not changed my settings since then. However, I’ve had two separate files fail on me since then and neither of them were removed from SAB, nor marked in Drone as failed. The most recent of these was the most recent episode of Brew Dogs. From my logs:
14-7-25 00:02:20.6|Info|Sabnzbd|Adding report [Brew.Dogs.S02E05.720p.HDTV.x264-YesTV] to the queue.
14-7-25 00:02:21.3|Info|DownloadService|Report sent to download client. Brew.Dogs.S02E05.720p.HDTV.x264-YesTV
14-7-25 00:02:22.1|Info|RssSyncService|RSS Sync Completed. Reports found: 300, Reports downloaded: 1
However, later on I found the following:
14-7-25 00:25:17.5|Warn|FailedDownloadService|[Brew.Dogs.S02E05.720p.HDTV.x264-YesTV] Download Failed, waiting for retry interval to expire.
This is the last entry I found in the logs about this file. It either never retried the file (not that that helps, as I did that manually) or it didn’t log that it did.
Drone itself is showing an empty progress bar for the episode and when I hover over it, I get: Episode is downloading - NaN% Brew.Dogs.S02E05.720p.HDTV.x264-YesTV
I didn’t have debug logging on at the time and I fixed my issue by removing the failed download and readding them. Will post debug logs if/when this occurs again.
I’m in the same boat as well. I don’t have debug logging on, but I have a show that drone grabbed. It failed in SAB (short blocks), and drone still has the purple color and downloading circle on the calendar. Exact same error log as NMe posted.
I enable debug logging and mark the download as failed. Maybe another one will occur.
If you enable debug logging and do nothing, drone will still be processing it and some useful information can be gathered. Since you manually intervened you will need to wait for the next failed download.
Considering my settings I’d at least expect to see a “retrying failed download” message in there after 60 and 120 minutes though?
Anyway, I had another download fail. In addition to the same symptoms above, I now have some debug logs:
14-7-27 12:47:20.3|Debug|SabnzbdProxy|Url: http://localhost:8080/api?mode=queue&start=0&limit=0&apikey=&output=json
14-7-27 12:47:20.3|Debug|SabnzbdProxy|Url: http://localhost:8080/api?mode=history&start=0&limit=30&apikey=&output=json
14-7-27 12:47:20.3|Debug|Parser|Parsing string ‘Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD’
14-7-27 12:47:20.3|Debug|Parser|Episode Parsed. epicmealempire - S01E02
14-7-27 12:47:20.3|Debug|Parser|Language parsed: English
14-7-27 12:47:20.3|Debug|NzbDrone.Core.Parser.QualityParser|Trying to parse quality for Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD
14-7-27 12:47:20.3|Debug|Parser|Quality parsed: HDTV-720p
14-7-27 12:47:20.3|Debug|Parser|Release Group parsed: DHD
This is in there a lot of time, probably around once every 10 seconds. Sometimes without the first 2 lines. I can find nothing else related in the logs, but I only turned them on after the download failed. I must have either forgotten to turn on debug logging or it must have turned itself off after my NAS rebooted for an update yesterday.
Hmm, just found these too:
14-7-27 12:47:53.6|Debug|FailedDownloadService|[Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD] Download Failed, waiting for retry interval to expire.
14-7-27 12:47:53.6|Debug|FailedDownloadService|[Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD] Recent release Failed, do not blacklist.
The first retry interval is in about 7 minutes so I’ll update this post when we get there.
Edit: When the update interval was over, it kept just doing the same things I mentioned above. About 5 minutes after that, I got this:
14-7-27 13:09:39.5|Debug|SabnzbdProxy|Url: http://localhost:8080/api?mode=queue&start=0&limit=0&apikey=&output=json
14-7-27 13:09:39.6|Debug|SabnzbdProxy|Url: http://localhost:8080/api?mode=history&start=0&limit=30&apikey=&output=json
14-7-27 13:09:39.6|Debug|Parser|Parsing string ‘Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD’
14-7-27 13:09:39.6|Debug|Parser|Episode Parsed. epicmealempire - S01E02
14-7-27 13:09:39.6|Debug|Parser|Language parsed: English
14-7-27 13:09:39.6|Debug|NzbDrone.Core.Parser.QualityParser|Trying to parse quality for Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD
14-7-27 13:09:39.6|Debug|Parser|Quality parsed: HDTV-720p
14-7-27 13:09:39.6|Debug|Parser|Release Group parsed: DHD
14-7-27 13:09:39.6|Debug|DownloadTrackingService|Item removed from download client by user: 1-SABnzbd_nzo_jktiSO: Epic.Meal.Empire.S01E02.The.Feast.and.the.Furious.720p.HDTV.x264-DHD
I did not remove anything from SAB and it’s actually still in the history list. I don’t think this is related to me upgrading SAB to 0.7.18 yesterday since the problem occurred earlier than that as well, but I guess I should mention it.
There are a couple of things happening that you need to understand, to avoid tripping over every logline
CDH does its checks only once a minute. However, the Queue UI (when open) will poll the download client every 30 sec. So, if the queue is open, then you’ll see an average of 3 polls per minute.
So everytime you see the SabnzbdProxy history/queue url pop up in the log, it’s either CDH fetching the data and processing it, or it’s the Queue fetching the data (and not processing it). The Queue uses it to update the ETA stuff at a higher frequency.
Debug "Download Failed, waiting for retry interval to expire."
You ought to see this every minute till the interval expires. It’s logged only once at Warn level (so it shows up on the UI).
Sabnzbd will assign the download a new ID when we tell it to Retry, In version 2.0.0.1690 we implemented a method of tracking that. (dunno the exact dev version that was first fixed)
Before that drone would lose track of the retried download. I doubt that’s the case here, but I need to know what happens earlier.
The gap during Edit is crucial, post the log from 14-7-27 12:47 till 13:10 on pastebin.
I figured that. I didn’t think anything was wrong there, I actually expected that log. I was mostly trying to be complete without posting a complete log file.
I haven’t seen it in the UI and I’ve only seen it in the logs once. Only for the initial failed download.
That’s what I thought at first too but I figured I’d at least see a log that it was retrying the download, and there is none of those in there as far as I can see.
The next couple of lines is ‘history,retry,queue’ which is how drone tries to get the new nzo ID. It simply matches the title.
However, this piece of code jumps out if multiple items in the queue have the same title.
Drone should be logging (At Debug) “[…] Changed id from … to …”.
What is possible is that the item hasn’t be added to the queue yet, (drone being too fast, or sab yet again not updating it’s internal state before returning the api retry call)
At line 5029 the existing history item disappears. Interestingly a new item doesn’t appear to be added.
But at line 5055 FailedDownloadService is rejecting a download… the one that “doesn’t appear to be added”.
That one puzzles me. Ow wait, forgot to move that one to Debug, it’s logging “Started tracking download” as Trace atm.
Anyway, Drone isn’t getting the new ID. Probably a timing issue.
I just tested this with some failed downloads and there is no changed:
14-7-28 20:02:09.7|Debug|FailedDownloadService|[Mythbusters.S05E16.720p.HDTV-x264-HDCP] Download wasn’t grabbed by drone or not in a category, ignoring download.
Here is the SAB call while the file is downloading:
Sry Snupple, we can’t work with individual loglines.
The logline you provided would be perfectly expected in certain scenarios.
Without context it is absolutely impossible to determine the sequence of events.
If you enabled Debug log after it happened, then there will be nothing useful in the logs.
I didn’t think anything was wrong there, I actually expected that log. I was mostly trying to be complete without posting a complete log file. 