Lots of orphaned directories and video files with 6.80RC1

[enchant]

[Reposting this. I originally put it into the wrong sub-forum, I think.]

I've had Newsbin working with Sonarr for a while now with few problems. There will occasionally be the stray abandoned directory or files in the main download directory, but nothing much. Lately I've had the problem where there are a ton of obfuscated files and no successfully downloaded videos. I installed 6.80RC1, and that seems to have solved that problem.

This morning I checked in the directory where files are unrarred and there were a few directories and video files in there, obviously done by Sonarr, because they were renamed. Then I checked in my main download directory. No obfuscated file names, but there were 13 directories. Each one contained a video file. And many multiples. Four directories containing what appear to be different versions of the same episode of a show. Three directories for another show, etc.

I don't know if this is a problem with Sonarr or Newsbin, but the problem started with the recent upgrade. My gut tells me that Sonarr is failing somehow, because it decides what Newsbin should download, and why is it downloading so many copies of one episode?

[enchant]

The problem continues today. Overnight, two files were correctly handled - downloaded and then renamed by Sonarr into their proper final directories. Twelve other new directories exist in my main download directory, containing what appear to be perfectly good video files. They were downloaded, but not renamed and moved into their proper directories.

FWIW, I tried downloading a show from within Newsbin without using Sonarr. It downloaded and unrarred into the unrar directory. So it seems like there is a breakdown between Newsbin and Sonarr with the latest update.

[Quade]

So you think Sonarr just keeps sending the same NZB's down? Or is the problem that Sonarr isn't renaming and moving the video files?

Are you seeing Sonarr talking to Newsbin in the logging tab?


Edit:

I'm looking at the Sonar logs after I downloaded something with an NZB and I can see Sonar grabbing the history and processing it. This is RC2 I'm using though.

[enchant]

So you think Sonarr just keeps sending the same NZB's down? Or is the problem that Sonarr isn't renaming and moving the video files?

I don't think it's sending the same NZB. They appear to be different versions of the same show. Here are a few of what I have:
A.Sample.Show.S02E08.720p.HDTV.x264-AVS.mkv
A.Sample.Show.S02E08.iNTERNAL.720p.WEB.x264-BAMBOOZLE.mkv
A.Sample.Show.S02E08.Leap.to.Faith.720p.NF.WEB-DL.DD5.1.x264-AJP69.mkv

But yes, the problem seems to be that Sonarr isn't moving and renaming the files. It's only doing half the job. I don't fully understand how the handshaking works. I assume it's vaguely like this:
Sonarr: Hey Newsbin, here's an NZB.
Newsbin: Sonarr, finished downloading it. It's located here...

So possibly Newsbin isn't giving Sonarr that second message?

Are you seeing Sonarr talking to Newsbin in the logging tab?

I'll PM you a section of the log where I turned debug on. I do see some interaction with Sonarr.

[Quade]

Sonarr: Hey Newsbin, here's an NZB.
Newsbin: Sonarr, finished downloading it. It's located here...

It's more like this:

S:-> Here's an NZB
S:-> What's your download list look like
N:-> Current Downloads that came from NZB
S:-> What's your history list look like
N:-> Finished Downloads that came from NZB
....
S:-> What's your download list look like
N:-> Current Downloads that came from NZB
S:-> What's your history list look like
N:-> Finished Downloads that came from NZB

Sonar: Ah an NZB finished and the file is in folder X:\UnRAR\. Let me grab that file and do things to it.

I'm checking the trace log and doing more tests. You might want to enable trace logging in Sonar and see what Sonarr thinks when it's talking to Newsbin

[enchant]

As far as I can tell, the highest level of logging on Sonarr is "info". Here is the log in the time vicinity of the Newsbin log I sent you:

18-1-5 07:37:30.6|Info|EpisodeSearchService|Episode search completed. 0 reports downloaded.
18-1-5 07:49:58.2|Info|RssSyncService|Starting RSS Sync
18-1-5 07:49:59.8|Info|DownloadDecisionMaker|Processing 335 releases
18-1-5 07:50:01.5|Info|RssSyncService|RSS Sync Completed. Reports found: 335, Reports grabbed: 0
18-1-5 07:54:42.5|Info|NzbSearchService|Searching 4 indexers for [Show Show (2016) : S02E09]
18-1-5 07:54:56.7|Info|DownloadDecisionMaker|Processing 10 releases
18-1-5 07:55:01.2|Info|Sabnzbd|Adding report [Show.Show.AU.S02E09.HDTV.x264-W4F] to the queue.
18-1-5 07:55:02.0|Info|DownloadService|Report sent to newsbin. Show.Show.AU.S02E09.HDTV.x264-W4F
18-1-5 08:05:29.8|Info|RssSyncService|Starting RSS Sync
18-1-5 08:05:31.4|Info|DownloadDecisionMaker|Processing 335 releases
18-1-5 08:05:33.2|Info|RssSyncService|RSS Sync Completed. Reports found: 335, Reports grabbed: 0
18-1-5 08:21:01.7|Info|RssSyncService|Starting RSS Sync

[Quade]

Under "Files" in the log tab, they should list the trace log. You might need to enable some setting in Sonarr to make it log at that detail level.

One thing I've noticed in my testing is that Sonarr can't handle long paths. I tested with a long NZB Filename and Newsbin renamed to use that NZB Filename which blew over 255 chars so, Sonarr couldn't pick up the files. You might want to make sure to use a shallow download and unrar path.

If this is your problem, I might need to enforce short paths and NZB Filenames for Sonarr.

[enchant]

I got trace logging turned on. The log file is kinda large. How can I send that to you? I'm unable to attach .txt or .zip files.

[Quade]

You could just interpret it yourself. You should be able to see Sonarr polling Newsbin and then when a download completes see Sonar do something with the files. You could clear the log then force a Sonarr download and watch the whole process.

You can email the log to [email protected] too.

I was testing an NZB that contained a MP4 file. I noticed it went to the failed list because the MP4 had no par files and there was no way to verify it. You might look in the failed list. Right now, the goal is to ID why Sonarr doesn't pick up most of the downloaded files. All the files I tested that completed and ended only in the files list ended up getting picked up by Sonarr.

Is Sonarr running on the same machine as Newsbin

[enchant]

You could just interpret it yourself.

I found this:

Code: Select all

18-1-5 15:58:33.9|Trace|ConfigService|Using default config value for 'downloadclientworkingfolders' defaultValue:'_UNPACK_|_FAILED_'
18-1-5 15:58:33.9|Debug|UpgradeSpecification|This file isn't an upgrade for all episodes. Skipping F:\Pat's temp\Newsbin download temp dir\Show.Name.2016.S02E05.720p.HEVC.x265-MEGUSTA English.nzb\The.Show.Name.S02E05.720p.HEVC.x265-MEGUSTA English.mkv
18-1-5 15:58:33.9|Debug|ImportDecisionMaker|File rejected for the following reasons: [Permanent] Not an upgrade for existing episode file(s)
18-1-5 15:58:33.9|Trace|ConfigService|Using default config value for 'removecompleteddownloads' defaultValue:'False'
18-1-5 15:58:33.9|Trace|EventAggregator|Publishing TrackedDownloadRefreshedEvent
18-1-5 15:58:33.9|Trace|EventAggregator|TrackedDownloadRefreshedEvent -> QueueService

So it could be that it's not renaming the file, because a better one was already downloaded and renamed. But some of the abandoned files/directories are for episodes that haven't been downloaded yet.

Is Sonarr running on the same machine as Newsbin

Yes.

I'm still running tests and looking at logs.

[Quade]

That's a pretty interesting note. It suggests sonarr is downloading a bunch of NZB's for the same show. In the looks you should see some json text that starts with "History" it's a list of downloaded NZB's. Night be interesting to note how many are getting reported to Sonarr and if any of them are listed as "Failed".

[enchant]

I'm not paying attention most of the time that stuff is happening, but I kind of assumed that Sonarr looked at the NZB and made a determination IF it should be downloaded, rather than downloading everything and then deciding if it's worth keeping. I'm really glad that I've got an unlimited account.

So maybe it's mostly working like it used to but it's suddenly not deleting the rejects anymore.

[Quade]

So far there are no other reports of this with RC2. I'm not clear if it's a problem in Newsbin or a Sonarr setting problem so at the moment the jury's still out.

The logs are pretty descriptive of what Sonarr is thinking. It should give some indication about why it's downloading a particular NZB.

[enchant]

I dunno what's going on. It seems suspicious that this happened when I upgraded Newsbin, but all of the evidence is pointing to Sonarr. Sonarr is supposed to decide what gets downloaded and Sonarr is supposed to rename it once it's done. It appears that Newsbin is doing its job.

I'm noticing a lot of strangeness in Sonarr that might have something to do with it. Last night I left the Sonarr website opened on a show that I expected to download. When I got up this morning, under the status for that episode, there was a "downloading" icon showing. The show had finished downloading hours earlier and was in my main download directory.

I checked through the trace log and Sonarr reported that that file had been rejected because it had been blacklisted. If I searched for posts for that episode in Sonarr, sure enough, ALL of the 720p files were marked as blacklisted. I wish the logs would explain WHY a file gets blacklisted. I checked, and the one that downloaded looked fine to me. The few 1080p versions of that episode were all marked ok, so I altered the profile that I had set for my downloads and included all of the 1020p qualities. A 1020p version downloaded and was moved successfully into place.

Don't know why I'm telling you all this, because this certainly doesn't seem to have anything to do with Newsbin.

[enchant]

I asked about all the blacklisting on the Sonarr reddit group and got this response:

A release gets blacklisted for one of many reasons: It's password-protected, it's incomplete, it's actually the wrong thing but mis-named, and so on. You should check your sab or nzbget program to see why it failed. Blacklisting just means that sab or nzbget told Sonarr that it failed, and so Sonarr is marking it as blacklisted so it doesn't try to grab it again in the future.

I'm afraid I know nothing about sab or nzbget. Does Newsbin replace those? And if so, does this information shed any light?

Also, I'm seeing a ton of these sorts of messages in the newsbin log:

[01/06 07:40:41] DEBUG NNTPServer: Post doesn't seem to be the post requested :9fba9dae812e4a0fa5d334ab339f1802 "9fba9dae812e4a0fa5d334ab339f1802.vol31+32.par2" yEnc - lQLupiwKLpnvS5Im5n6G

[Quade]

Newsbin is just another downloader to Sonarr. It replaces Sab in this case.

I asked someone I know who uses Sonarr and Newsbin he says it's working well for him and he's not getting these duplicate downloads.

[01/06 07:40:41] DEBUG NNTPServer: Post doesn't seem to be the post requested :9fba9dae812e4a0fa5d334ab339f1802 "9fba9dae812e4a0fa5d334ab339f1802.vol31+32.par2" yEnc - lQLupiwKLpnvS5Im5n6G

This isn't unusual for obscured files. Some are posted damaged in purpose.

Are files ending up in the failed list? I'd expect files that get re-downloaded to be re-downloaded because they went to the failed list. It might be a good idea to wipe the download folder after a run and then watch a day's worth of downloads to see if you can characterize this.

[enchant]

A show airs and it gets posted in various resolutions. Some resolutions get posted by different groups, so while a 720p gets posted that is 1.2G, someone else posts one that is only 940M, and another comes in at 2.8G.

Now this part is just what I can see, so I can't make any determinations about what is *actually* going on.

Sonarr finds an nzb for an episode I want. I have to assume that it wouldn't download a "blacklisted" release. Newsbin downloads that episode and puts it in a directory. Sonarr downloads another one. After each download, the Sonarr's status on that episode changes to "blacklisted".

Ask your friend what resolution he typically downloads. I generally go for 720p. This morning, I edited my "720" profile to also include anything that's 1080p. Since then, a couple of shows have downloaded and successfully been moved into their correct series directories. These are shows that were previously downloaded at 720 resolutions and were abandoned in the main download directory.

Are files ending up in the failed list?

No. The failed list has remained empty for a few days. And yes, I do clear out the download folder each day.

There's nothing on tonight, so I probably won't know much more till Monday morning.

[Quade]

A show airs and it gets posted in various resolutions. Some resolutions get posted by different groups, so while a 720p gets posted that is 1.2G, someone else posts one that is only 940M, and another comes in at 2.8G.

Are you asking Sonar to download all the reses?

Sonarr finds an nzb for an episode I want. I have to assume that it wouldn't download a "blacklisted" release. Newsbin downloads that episode and puts it in a directory. Sonarr downloads another one. After each download, the Sonarr's status on that episode changes to "blacklisted".

This is the key point. Why is Sonarr downloading more of the same? It sounds like a setting. I wonder if it's a sequence problem where it downloads a high res before a low res so, any low-res downloads that happen after the fact are ignored. That's what the symptoms point to.

[enchant]

Are you asking Sonar to download all the reses?

No. It goes like this...

Sonarr has its hierarchy of the quality of a video.

480p < 720p-hd < 720p WEB-DL < 1080p-hd < 1080p Web-DL ...etc

So I tell Sonarr that I'll be happy with 720p WEB-DL. That's the cutoff point. Once Sonarr successfully gets at least that quality, it considers the job done. I also tell Sonarr that I'm willing to take:
480p
720-hd
720 web-dl
1080-hd
1080 web-dl
...so that if the quality I want never gets posted, at least I've got something.

So here are a couple scenarios:

For a specific episode, the first post it finds is a 1080p-hd. It downloads that, and since 1080p-hd is better than the 720p web-dl cutoff, it's done with that episode.

For a different episode, it first finds a 480p and downloads that. An hour later, it finds a 720-hd, downloads that and removes the 480 from before. At this point, the 720 web-dl cutoff has not yet been met. A couple hours later, it finds a 1080 web-dl, downloads that and removes the 720-hd. At this point, the cutoff has been met and we're done with that episode.

Now I don't really know all of the handshaking that goes on between Sonarr and Newsbin, but I think that what can happen is that Sonarr gets an NZB for a show that I need, let's say "I Love Lucy, S02E04". It gives that to Newsbin. Newsbin downloads it, but when extracted, it's actually a binary install file for Photoshop. So (I think) it tells Sonarr that that NZB file is bad. Sonarr blacklists that NZB and continues to wait for another NZB for that episode.

[Quade]

Now I don't really know all of the handshaking that goes on between Sonarr and Newsbin,

I described it above.

Newsbin downloads it, but when extracted, it's actually a binary install file for Photoshop.

Are you actually seeing that? I never have. If so it suggests your source of NZB's ain't so hot. If what you're describing is really what's happening then I'd say there's nothing wrong and you'll just have to clean out the unrar folder from time to time. Newsbin is a conduit. It just downloads what you (or Sonarr) tells it to download. The decision making about what to download in the case of using Sonarr is completely out of Newsbin's control.

What I'm looking for is whether Sonarr is getting confused by something Newsbin is saying to it. If a download succeeds but Sonarr thinks it doesn't for example. That's something I can fix. I can't fix spurious NZB's.

[enchant]

Newsbin downloads it, but when extracted, it's actually a binary install file for Photoshop.

Are you actually seeing that?

I'm not seeing that specifically. That's an extreme example that I made up. Something more realistic might be if it's expecting S04E08 and it got S04E07 perhaps. I don't know how often this happens. Much goes on when I'm not watching. But from time to time, I'll notice that Newsbin is downloading a "better version" of a show that I watched yesterday.

What I'm looking for is whether Sonarr is getting confused by something Newsbin is saying to it. If a download succeeds but Sonarr thinks it doesn't for example. That's something I can fix. I can't fix spurious NZB's.

Someone on the Sonarr reddit group said this:

Newsbin (which, yes, replaces sab or nzbget) just says "it's bad", Sonarr says "okay, thanks, I'll blacklist it and try another release if there is one."

Newsbin will have the actual information on exactly why it failed. But what's important is that it failed for a valid reason, and it's not actually a good download.

I have no way of knowing if this person is correct. It would certainly explain what I'm seeing. When I look through Sonarr's logs, I don't see anything obvious saying something like "Newsbin says the download is bad for 'x' reason." It just says

Code: Select all

18-1-6 02:37:39.6|Debug|BlacklistSpecification|Show.Name.S08E12.720p.HDTV.X264-DIMENSION-xpost is blacklisted, rejecting.

Is it blacklisted because of something Newsbin said? Is it blacklisted because Sonarr looked at the download and made that determination? I don't know.

[Quade]

Is it blacklisted because of something Newsbin said? Is it blacklisted because Sonarr looked at the download and made that determination? I don't know.

I've never seen Sonarr blacklist anything to be honest. If the files aren't going to the failed list, they won't get reported as "failed" to sonarr. When sonarr asks for the history, it just asks for the last 30 records. I wonder if there's some timing issue where the downloads are so fast and you're downloading so much that the history for some files is already more than 30 away?

The fact Sonarr is black listing things would explain your symptoms though.