Remote path mapping looks for blank filename

fadedhype · July 10, 2018, 4:57am

Sonarr version (exact version):
2.0.0.5228

Mono version:
5.12.0.226

OS:
CentOS 7-1804

Couldn't import episode /downloads/completed/series-redacted/episode-redacted.mkv: Could not find file ""

System.IO.FileNotFoundException: Could not find file ""
  at System.IO.File.Move (System.String sourceFileName, System.String destFileName) [0x00116] in <71d8ad678db34313b7f718a414dfcb25>:0 
  at NzbDrone.Common.Disk.DiskProviderBase.MoveFileInternal (System.String source, System.String destination) [0x00000] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskProviderBase.cs:232 
  at NzbDrone.Mono.Disk.DiskProvider.MoveFileInternal (System.String source, System.String destination) [0x00076] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Mono\Disk\DiskProvider.cs:170 
  at NzbDrone.Common.Disk.DiskProviderBase.MoveFile (System.String source, System.String destination, System.Boolean overwrite) [0x000e3] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskProviderBase.cs:227 
  at NzbDrone.Common.Disk.DiskTransferService.TryCopyFileTransactional (System.String sourcePath, System.String targetPath, System.Int64 originalSize) [0x00108] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskTransferService.cs:462 
  at NzbDrone.Common.Disk.DiskTransferService.TransferFile (System.String sourcePath, System.String targetPath, NzbDrone.Common.Disk.TransferMode mode, System.Boolean overwrite, NzbDrone.Common.Disk.DiskTransferVerificationMode verificationMode) [0x0034a] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskTransferService.cs:289 
  at NzbDrone.Common.Disk.DiskTransferService.TransferFile (System.String sourcePath, System.String targetPath, NzbDrone.Common.Disk.TransferMode mode, System.Boolean overwrite, System.Boolean verified) [0x0000e] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskTransferService.cs:196 
  at NzbDrone.Core.MediaFiles.EpisodeFileMovingService.TransferFile (NzbDrone.Core.MediaFiles.EpisodeFile episodeFile, NzbDrone.Core.Tv.Series series, System.Collections.Generic.List`1[T] episodes, System.String destinationFilePath, NzbDrone.Common.Disk.TransferMode mode) [0x0012c] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Core\MediaFiles\EpisodeFileMovingService.cs:119 
  at NzbDrone.Core.MediaFiles.EpisodeFileMovingService.CopyEpisodeFile (NzbDrone.Core.MediaFiles.EpisodeFile episodeFile, NzbDrone.Core.Parser.Model.LocalEpisode localEpisode) [0x0006b] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Core\MediaFiles\EpisodeFileMovingService.cs:94 
  at NzbDrone.Core.MediaFiles.UpgradeMediaFileService.UpgradeEpisodeFile (NzbDrone.Core.MediaFiles.EpisodeFile episodeFile, NzbDrone.Core.Parser.Model.LocalEpisode localEpisode, System.Boolean copyOnly) [0x00167] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Core\MediaFiles\UpgradeMediaFileService.cs:72 
  at NzbDrone.Core.MediaFiles.EpisodeImport.ImportApprovedEpisodes.Import (System.Collections.Generic.List`1[T] decisions, System.Boolean newDownload, NzbDrone.Core.Download.DownloadClientItem downloadClientItem, NzbDrone.Core.MediaFiles.EpisodeImport.ImportMode importMode) [0x00272] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Core\MediaFiles\EpisodeImport\ImportApprovedEpisodes.cs:107

Description of issue:
I set up a remote path mapping to correlate a remote container with Sonnar’s. An ls -l of both the local and remote episode’s directory displays the file, as well as its 777 chmod. Debug logs show that Sonarr cannot locate "", a blank filename, apparently. The hostnames of the download client and remote mapping match exactly. Mapping remote /data to local /downloads. I can confirm that the local path Sonarr is searching is the correct path. Tested moving the episode as the sonarr user with no issues.

Taloth · July 10, 2018, 5:06pm

Can you provide trace level log file entries? That’ll show the source and destinations paths. The “Debug logs” text in your post contains a link with instructions.

fadedhype · July 10, 2018, 10:29pm

Thanks for the reply. I am not able to reproduce this issue with anything other than Sonar itself.

Here’s what I saw that seemed relevant:

18-7-10 18:01:59.7|Debug|ImportDecisionMaker|File accepted
18-7-10 18:01:59.7|Debug|Parser|Parsing string 'Series.Name.S01E22.1080p.WEBRip.DDP5.1.x264-BTN[releasegroup]'
18-7-10 18:01:59.7|Trace|Parser|^(?<title>.+?)(?:(?:[-_\W](?<![()\[!]))+S?(?<season>(?<!\d+)(?:\d{1,2})(?!\d+))(?:[ex]|\W[ex]|_){1,2}(?<episode>\d{2,3}(?!\d+))(?:(?:\-|[ex]|\W[ex]|_){1,2}(?<episode>\d{2,3}(?!\d$
18-7-10 18:01:59.7|Debug|Parser|Episode Parsed. Series Name - S01E22
18-7-10 18:01:59.7|Debug|Parser|Language parsed: English
18-7-10 18:01:59.7|Debug|QualityParser|Trying to parse quality for Series.Name.S01E22.1080p.WEBRip.DDP5.1.x264-BTN[releasegroup]
18-7-10 18:01:59.7|Debug|Parser|Quality parsed: WEBDL-1080p v1
18-7-10 18:01:59.7|Debug|Parser|Release Group parsed: BTN
18-7-10 18:01:59.7|Debug|MediaInfoFormatter|Formatting audio channels using 'AudioChannelPositions', with a value of: '3/2/0.1'
18-7-10 18:01:59.7|Debug|EpisodeFileMovingService|Copying episode file: /downloads/completed/Series.Name.S01E22.1080p.WEBRip.DDP5.1.x264-BTN[releasegroup]/Series.Name.S01E22.1080p.WEB-DL.DDP5.1.H.264-NTb.mkv to /tv/Series Name/Season 1/Series Name - S01E22 - WEBDL-1080p.mkv
18-7-10 18:01:59.7|Debug|DiskTransferService|Copy [/downloads/completed/Series.Name.S01E22.1080p.WEBRip.DDP5.1.x264-BTN[releasegroup]/Series.Name.S01E22.1080p.WEB-DL.DDP5.1.H.264-NTb.mkv] > [/tv/Series Name/Season 1/Series Name - S01E22 - WEBDL-1080p.mkv]
18-7-10 18:01:59.8|Trace|SymbolicLinkResolver|Checking path /tv/Series Name/Season 1/Series Name - S01E22 - WEBDL-1080p.mkv for symlink returned error ENOENT, assuming it's not a symlink.

Performing the copy manually as the sonarr user from within the container, the transfer goes flawlessly.

docker exec -it sonarr cp /downloads/completed/Series.Name.S01E22.1080p.WEBRip.DDP5.1.x264-BTN[releasegroup]/Series.Name.S01E22.1080p.WEB-DL.DDP5.1.H.264-NTb.mkv /tv/Series\ Name/Season\ 1/Series\ Name\ -\ S01E22\ -\ WEBDL-1080p.mkv

fadedhype · July 10, 2018, 10:51pm

Just one more thing…I feel like this has something to do with the .partial~ file that Sonarr creates when it’s copying to my goofys-mounted S3 bucket (with an internal S3 endpoint).

After searching, I read that Sonarr will cancel the copy if the filesizes don’t match, but they do. Both are 482732988 bytes. From what I saw, it didn’t take Sonarr long to give up and delete the .partial~ file after fully completing the transfer.

I don’t think I should need the partial upload feature. Any way to disable that and test without?

Taloth · July 12, 2018, 5:37am

The log file cuts off. It’s basically not even begun copying yet.

fadedhype · July 23, 2018, 10:53pm

Hey @Taloth, I DMed you a link to the full log. Let me know what you think. Thank you!

Taloth · July 24, 2018, 6:11pm

18-7-23 18:42:27.6|Debug|EpisodeFileMovingService|Moving episode file: /downloads/completed/Series.Title.S01E21.720p.HDTV.x264-AVS[rarbg]/Series.Title.S01E21.720p.HDTV.x264-AVS.mkv to /tv/Series Title/Season 01/Series Title - S01E21 - HDTV-720p.mkv
18-7-23 18:42:27.6|Debug|DiskTransferService|Move [/downloads/completed/Series.Title.S01E21.720p.HDTV.x264-AVS[rarbg]/Series.Title.S01E21.720p.HDTV.x264-AVS.mkv] > [/tv/Series Title/Season 01/Series Title - S01E21 - HDTV-720p.mkv]
18-7-23 18:42:27.9|Trace|SymbolicLinkResolver|Checking path /tv/Series Title/Season 01/Series Title - S01E21 - HDTV-720p.mkv for symlink returned error ENOENT, assuming it's not a symlink.
18-7-23 18:42:27.9|Trace|DiskTransferService|Removing old backup.
18-7-23 18:42:27.9|Trace|DiskProviderBase|Deleting file: /downloads/completed/Series.Title.S01E21.720p.HDTV.x264-AVS[rarbg]/Series.Title.S01E21.720p.HDTV.x264-AVS.mkv.backup~
18-7-23 18:42:28.0|Trace|DiskTransferService|Removing old partial.
18-7-23 18:42:28.0|Trace|DiskProviderBase|Deleting file: /tv/Series Title/Season 01/Series Title - S01E21 - HDTV-720p.mkv.partial~
18-7-23 18:42:28.1|Trace|DiskTransferService|Attempting to move hardlinked backup.
18-7-23 18:43:47.6|Warn|ImportApprovedEpisodes|Couldn't import episode /downloads/completed/Series.Title.S01E21.720p.HDTV.x264-AVS[rarbg]/Series.Title.S01E21.720p.HDTV.x264-AVS.mkv
 
[v2.0.0.5228] System.IO.FileNotFoundException: Could not find file ""
  at System.IO.File.Move (System.String sourceFileName, System.String destFileName) [0x00116] in <71d8ad678db34313b7f718a414dfcb25>:0
  at NzbDrone.Common.Disk.DiskProviderBase.MoveFileInternal (System.String source, System.String destination) [0x00000] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskProviderBase.cs:232
  at NzbDrone.Mono.Disk.DiskProvider.MoveFileInternal (System.String source, System.String destination) [0x00076] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Mono\Disk\DiskProvider.cs:170
  at NzbDrone.Common.Disk.DiskProviderBase.MoveFile (System.String source, System.String destination, System.Boolean overwrite) [0x000e3] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskProviderBase.cs:227
  at NzbDrone.Common.Disk.DiskTransferService.TryMoveFileTransactional (System.String sourcePath, System.String targetPath, System.Int64 originalSize, NzbDrone.Common.Disk.DiskTransferVerificationMode verificationMode) [0x000ba] in C:\BuildAgent\work\5d7581516c0ee5b3\src\NzbDrone.Common\Disk\DiskTransferService.cs:498

DiskTransferService.cs:498 coincides with https://github.com/Sonarr/Sonarr/blob/12065948ca0b53d655e90e127800c44d6a08036a/src/NzbDrone.Common/Disk/DiskTransferService.cs#L498

Which means it completed the transfer, checked the filesize which was the same, and then instructed mono to rename the file from .mkv.partial~ to .mkv. Which caused
The copy action of 483 MB took 79 seconds, about 6.1 MB/s. Pretty slow imo, but matches what one would expect with s3.

Another thing that surprises me is that the transfer deletes both an old backup and old partial. I would’ve expected the old partial, but not the old backup.

Anyway, the blank string “” isn’t actually a blank string. That’s just mono not knowing how to log errors. Under the hood it’s just an ambiguous “File not Found” error.
It’s probably possible to get more mono internal traces with mono trace/debug options, but that’s not worth the effort. It could be more useful to trace what’s happening in that goofys filesystem driver. A quick google indicates that there are fstab flags to debug fuse and/or s3.

fadedhype · July 25, 2018, 12:04am

I appreciate your looking into it. Truthfully, I’ve never been able to use s3fs or goofys for anything more than simple PUTs and GETs. The solution here is to use ObjectiveFS, which is the only S3-backed mount I’ve ever found with full POSIX support. It works great, and it’s fast, but far from being open source. I ended up buying a license, and Sonarr’s working great now.

Taloth · July 25, 2018, 3:22pm

Tnx for letting me know.

A lot of ppl actually use unionfs (or similar) and a sync tool to store new files locally in a cache and upload separately, one layer as write cache and the bottom layer as readonly of the cloud drive.

system · September 23, 2018, 3:22pm

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.