OSX Sierra/High Sierra - Can only copy large files to Cache Mount if nested

Animosity022 · April 29, 2018, 11:35am

blim5001 · April 29, 2018, 11:36am

In the zip file i downloaded was an rclone file as well as the rclone.1 file

Contents of the zip file

git-log.txt
rclone
rclone.1
README.html
README.txt

and the size of rclone is 31M

Running this version the finder now shows the mount as just gcache rather than gcache/

jrock · April 29, 2018, 1:32pm

OK thx, I downloaded too early, there were only two files available at the time and their titles included “osx” and “windows” in both zip filenames. Anyway, all versions available now, osx version downloaded and tested:

Thanks (!) @ncw, this fix removed the forward slash.
Breakthrough! I noticed that I can successfully copy un-nested larger files from source to the mounted cached remote in Finder without the error if…wait for it…in Finder I mark the file as “Get info” -> “Hide extension”.

The smaller files I was successfully copying before had their filename extensions hidden (they were text files created/recognised by OSX software). Also of course, the folders (with the nested larger files) I was successfully copying had no extensions in the folder name.

So I think the issue is related to rclone having an issue with the filename’s extension showing in the source folder. Unfortunately, there is no native way that I could find to automatically hide the extension for all current and future files in a folder/subfolders in Finder. It IS possible to select them all then use “Hide extension” or use a script to do it, but as soon as you add new files to source their extensions will not be hidden.

So whilst this gets us closer to a solution, it doesn’t look like there is a Finder workaround - probably still needs a fix in rclone’s handling of extensions (or is this an osxfuse thing?).

blim5001 · April 29, 2018, 2:08pm

Your right, Well done for finding that

Although that is so odd, especially as a file I just tried to copy has many dots in the name, so in the finder it still appears to have an extension, even after checking the box to hide extension…

for example if I get info on a file like this:

show.name.s01e12.episode.title.1080p.x264.mp4

then check the box to hide extension the file name does not actually change, but I can copy it to my mounted drive…

(At least the name does not change visually, although I did notice that I had the Show all filename extensions box checked in the advanced tab of Finder Preferences, I just tried unchecking that option, but then started getting error 36 and permission errors when trying to copy files into the mount, so I am leaving that checked for now)

I don’t think it would be osxfuse as I don’t have a problem copying files to sshfs mounts, but don’t know if the issue could be with the bazil fuse library or rclone. We will have to see what ncw thinks.

jrock · April 29, 2018, 3:07pm

One more data point:

In one of my earlier posts on this thread, I mentioned that rclone is leaving empty folders behind in the --cache-tmp-upload-path location. I just want to confirm that this is still occurring.

I have tested with rclone mount and sudo rclone mount, folders are not cleaned up under either. I also have the permissions for --cache-tmp-upload-path location set to read/write for all users/groups.

Note that files are cleaned up, but their copied parent directories are left behind.

Can umount then mount again, the folders are still not cleaned up.

Animosity022 · April 29, 2018, 5:33pm

When you say the folders aren’t cleaned up, that seems to be the same on Linux as well. Do the files get uploaded or no?

jrock · April 29, 2018, 5:33pm

Yes, the upload works fine, folders and files created correctly on GDrive.

jrock · April 30, 2018, 1:49am

There have been a few findings in this thread, just thought it would be helpful if I summarised where we are up to with these Mount-related issues:

OSX - Trailing forward slash on volume name: RESOLVED with the experimental release
OSX - Source files without “Hide extension” checked in Finder cannot be copied: UNRESOLVED
OSX - "exceeding limit of 150 wakeups per second over 300 seconds” kernel messages: NOT A BREAKING ISSUE at this stage
OSX and LINUX - --cache-tmp-upload-path folders not being cleaned up: UNRESOLVED and seems to be happening on Linux and OSX
OSX - Some rclone flags causing "-o/–option not supported with this FUSE backend” errors: NOT A BREAKING ISSUE at this stage.

ncw · April 30, 2018, 9:11am

thanks for your summary @jrock

How important is this fix? Shall I merge it to master? What I did was replace all : and / in remote:path/to/subdir into spaces so that would appear as a volume called remote path to subdir. Is that OK?

Also is it useful to specify the volume name on the command line?

I don’t understand this at all! This is all happening at a level above rclone and likely above OSXFUSE…

What we need to do is try to produce a pair of logs with and without that setting. So stop the mount and run rclone with -vv --log-file test1.log and do the test then stop the mount. Repeat with the setting the other way round to make test2.log. Try to do exactly the same thing so we get two comparable logs.

What may be happening is that OSX asks rclone for something else when the extensions are hidden/not hidden and hopefully we’ll be able to work it out from those two logs.

OK. Ideally I’d tell OSX that rclone is implementing a filesystem and is likely to have lots of wakeups, but I don’t know how to do that!

Can you please make a new issue on github about this so we’ve got it on the radar.

In the mean time if this bothers you, you can run rclone rmdirs on the path and it will delete any empty directories recursively…

Yes, that is a limitation of the fuse library I’m using.

If you compile rclone yourself on macOS with go build -tags cmount then rclone will gain a cmount command which works just like mount. This uses the C version of the fuse library.

Here is a binary: https://911-17803236-gh.circle-artifacts.com/0/tmp/rclone.dist/rclone-darwin-10.6-amd64 compiled like that.

This will support all the -o flags.

It would be interesting to see if rclone cmount behaves the same way as rclone mount for the issues listed too.

jrock · April 30, 2018, 10:11am

Thx again @ncw

When using Finder it is probably only cosmetic. But when using the command line (Terminal) it is difficult to refer to the Volume. Every variation I have tried on the command line cannot access (eg.) “Media/” as a volume. So I feel it should be in Master. As for the approach, that seems to be working and seems like a reasonable way to implement it.

This is the main outstanding breaking issue. I will run these tests and post the results when I get to my PC late tomorrow.

Done!

I will test it out and revert back. Not at my PC again until late tomorrow so there will be a brief delay.

jrock · May 1, 2018, 1:53pm

This post is about issue (2) above:

OK, so I haven’t had time to test cmount yet, but I have run the -vv tests and done some more research and here is what I have found:

OSX Filesystem / Finder

This all appears related to the com.apple.finderInfo extended attribute (henceforth xattr) on files in osx
When we use the backend cache with a cache-tmp-upload-path:
– IF the source file has a com.apple.finderInfo xattr, it copies ok
– IF the source file DOES NOT have a com.apple.finderInfo xattr, the copy fails.
– IF we copy a parent folder of source file(s), the folder and file contents copy fine regardless of xattr absence/existence on the files. (In OSX Folders themselves usually do not have any xattr’s).
Previously we focussed on the “Hide extension” xattr which is exposed by the “Get Info” context menu option in Finder. However, if we switch on the “Stationery pad” xattr (for example) in Get Info instead then we see the same behaviour. That is, whenever any of these options are selected on the source file, OSX attaches the com.apple.finderInfo xattr to that file. Disable these options and OSX removes the com.apple.FinderInfo xattr and copying fails.

[Side note: All of this behaviour is using the “Mac OS Extended (Journaled)” file system (ie. the HFS+ file system, not the new apfs file system used by new High Sierra installs - most of us have upgraded from Sierra and kept the existing file system)]

OSXFUSE

Now what’s also going on is that the rclone fuse mount is applying fuse option NoAppleXattr which strips any com.apple.FinderInfo xattr.

Backend Cache with --cache-tmp-upload-path

The error messages arise as rclone attempts to copy from the source to the cache-tmp-upload-path folder. Both of these locations are on the OSX filesystem, not on the mount.

So, it’s very thin…but my theory is that during the copy from the source to the cache-tmp-upload-path folder:

For source files with the xattr, the xattr’s are stripped by osxfuse in a manner that informs OSX that this is occurring. Being an xattr aware filesystem, OSX allows the stripped files to successfully copy into the cache-tmp-upload-path folder.
For source files already missing the xattr’s, no notification is made to OSX and as such OSX gets upset when xattr-less files are created in the cache-tmp-upload-path folder.
OR
Gets upset when osxfuse attempts to strip xattr’s that don’t exist.

Like I said…it’s thin…

What I would like to test is copying xattr-less source files with the fuse NoAppleXattr option disabled.

-vv Tests
As for the -vv tests, I don’t feel they showed much and both scenarios have “no such file or directory” errors which is confusing me.

Note: I used an encrypted cache but the unencrypted cache returns similar output.

Copying a file WITH the com.apple.finderInfo xattr:

2018/05/01 00:12:56 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274632384149 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/05/01 00:12:56 DEBUG : /: Lookup: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:12:56 DEBUG : /: Lookup: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:12:56 DEBUG : /: Lookup: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:12:56 DEBUG : /: Lookup: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:12:56 DEBUG : /: Lookup: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:12:56 DEBUG : /: Create: name=“Untitled2.rtf”
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: >Open: fd=Untitled2.rtf (w), err=
2018/05/01 00:12:56 DEBUG : /: >Create: node=Untitled2.rtf, handle=&{Untitled2.rtf (w)}, err=
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: Attr:
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r–, err=
2018/05/01 00:12:56 DEBUG : &{Untitled2.rtf (w)}: Flush:
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2018/05/01 00:12:56 DEBUG : &{Untitled2.rtf (w)}: >Flush: err=
2018/05/01 00:12:56 DEBUG : &{Untitled2.rtf (w)}: Release:
2018/05/01 00:12:56 DEBUG : Untitled2.rtf: WriteFileHandle.Release closing
2018/05/01 00:12:56 DEBUG : Encrypted drive ‘Media:’: File to upload is small (0 bytes), uploading instead of streaming
2018/05/01 00:12:56 DEBUG : Cache remote GdriveCache:: put data at ‘0nlqsgnip1e7ia64fravmrk38s’
2018/05/01 00:12:56 DEBUG : : cache: expired

Copying a file WITHOUT the com.apple.finderInfo xattr:

2018/05/01 00:10:30 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274632384149 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=
2018/05/01 00:10:30 DEBUG : /: Lookup: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:10:30 DEBUG : /: Lookup: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:10:30 DEBUG : /: Lookup: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:10:30 DEBUG : /: Lookup: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:10:30 DEBUG : /: Lookup: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : /: >Lookup: node=, err=no such file or directory
2018/05/01 00:10:30 DEBUG : /: Create: name=“Untitled.rtf”
2018/05/01 00:10:30 DEBUG : Untitled.rtf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/05/01 00:10:30 DEBUG : Untitled.rtf: >Open: fd=Untitled.rtf (w), err=
2018/05/01 00:10:30 DEBUG : /: >Create: node=Untitled.rtf, handle=&{Untitled.rtf (w)}, err=
2018/05/01 00:10:30 DEBUG : Untitled.rtf: Attr:
2018/05/01 00:10:30 DEBUG : Untitled.rtf: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r–, err=
2018/05/01 00:10:30 DEBUG : &{Untitled.rtf (w)}: Flush:
2018/05/01 00:10:30 DEBUG : Untitled.rtf: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2018/05/01 00:10:30 DEBUG : &{Untitled.rtf (w)}: >Flush: err=
2018/05/01 00:10:30 DEBUG : &{Untitled.rtf (w)}: Release:
2018/05/01 00:10:30 DEBUG : Untitled.rtf: WriteFileHandle.Release closing
2018/05/01 00:10:30 DEBUG : Encrypted drive ‘Media:’: File to upload is small (0 bytes), uploading instead of streaming
2018/05/01 00:10:30 DEBUG : Cache remote GdriveCache:: put data at ‘ed51h1l044n5gpu4e2mr7h1vo0’
2018/05/01 00:10:30 DEBUG : : cache: expired

Does any of this help?

ncw · May 1, 2018, 3:12pm

I put the NoAppleXattr option on because it was on an example I saw. rclone doesn’t support xattrs at all, so I assumed it was the correct thing to do…

Here is a build without it…

https://beta.rclone.org/v1.41-012-g4633280b-osx-volname/ (uploaded in 15-30 mins)

They look very similar don’t they… The “no such file or directory” is just the OS looking to see if “Untitled2.rtf” exists or not before creating it.

What is interesting is that according to those logs the transfer went fine - there aren’t any errors.

It would probably be worth repeating with the --debug-fuse flag as well which will be even more verbose! That will tell us if the OS called any of the xattr methods.

I’m wondering if rclone is returning the correct error for xattr methods that aren’t supported. It is currently returning ENOTSUPP, whereas rclone mount returns ENOSYS (Function not implemented) which is more typical of FUSE. These both work fine on linux though.

Having a quick squint at the source of osxfuse, I think returning ENOTSUPP is wrong and it should return ENOSYS - if it does that then OSXFUSE will only call xattr once and stop calling it.

It would be interesting for you to try rclone cmount which returns ENOSYS…

I’d have to patch the upstream library to fix that if it is really the problem.

blim5001 · May 1, 2018, 7:15pm

Just tried the beta from the previous post and so far it seems to be working

I have tried copying a few different files into the mount and the finder copied them all without any errors.

@jrock can you try that beta and see what happens.

jrock · May 2, 2018, 5:58am

Awesome, now we’re getting somewhere!

Test 1: Using the mount (not cmount) build with NoAppleXattr disabled, -vv & --debug-fuse
Files copy successfully (yay!).

The relevant part of the logged results around the xattr treatment seems to be:

> 2018/05/02 12:53:24 DEBUG : fuse: <- Getxattr [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=261] "com.apple.FinderInfo" 32 @0
> 2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Getxattr error=operation not supported

Below is the more complete extract:

2018/05/02 12:53:24 DEBUG : fuse: <- Getattr [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=261] 0x0 fl=0
2018/05/02 12:53:24 DEBUG : /: Attr: 
2018/05/02 12:53:24 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxrwxr-x, err=<nil>
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Getattr valid=1s ino=1 size=0 mode=drwxrwxr-x
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x2] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x6] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Statfs [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=261]
2018/05/02 12:53:24 DEBUG : : Statfs: 
2018/05/02 12:53:24 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274632384149 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Statfs blocks=274877906944/274632384149/274877906944 files=1000000000/1000000000 bsize=4096 frsize=4096 namelen=255
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x2
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x4
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x2] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x1
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x6] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Getxattr [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=261] "com.apple.FinderInfo" 32 @0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Getxattr error=operation not supported
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=261] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x2
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x4
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x2] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x1
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x6] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Getxattr [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=23537] "com.apple.FinderInfo" 32 @0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Getxattr error=operation not supported
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Statfs [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=23537] : Statfs: 
2018/05/02 12:53:24 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274632384149 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Statfs blocks=274877906944/274632384149/274877906944 files=1000000000/1000000000 bsize=4096 frsize=4096 namelen=255
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x1
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x2] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Lookup [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: Lookup: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x6] Lookup error=ENOENT
2018/05/02 12:53:24 DEBUG : fuse: <- Lookup [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: Lookup: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Lookup error=ENOENT
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Lookup [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: Lookup: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Lookup error=ENOENT
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x7 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Lookup [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: Lookup: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x2] Lookup error=ENOENT
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x6 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x6] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Lookup [ID=0x5 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: Lookup: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : /: >Lookup: node=<nil>, err=no such file or directory
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x5] Lookup error=ENOENT
2018/05/02 12:53:24 DEBUG : fuse: <- Access [ID=0x4 Node=0x1 Uid=501 Gid=20 Pid=23537] mask=0x2
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Access
2018/05/02 12:53:24 DEBUG : fuse: <- Create [ID=0x3 Node=0x1 Uid=501 Gid=20 Pid=23537] "Untitled2.rtf" fl=OpenReadWrite+OpenCreate+OpenExclusive mode=-rw-r--r-- umask=----------
2018/05/02 12:53:24 DEBUG : /: Create: name="Untitled2.rtf"
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: >Open: fd=Untitled2.rtf (w), err=<nil>
2018/05/02 12:53:24 DEBUG : /: >Create: node=Untitled2.rtf, handle=&{Untitled2.rtf (w)}, err=<nil>
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: Attr: 
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: >Attr: a=valid=1s ino=0 size=0 mode=-rw-rw-r--, err=<nil>
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x3] Create {0x4 gen=0 valid=1m0s attr={valid=1s ino=4894467398790886159 size=0 mode=-rw-rw-r--}} {0x2 fl=0}
2018/05/02 12:53:24 DEBUG : fuse: <- Flush [ID=0x7 Node=0x4 Uid=501 Gid=20 Pid=23537] 0x2 fl=0x0 lk=0x0
2018/05/02 12:53:24 DEBUG : &{Untitled2.rtf (w)}: Flush: 
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: WriteFileHandle.Flush unwritten handle, writing 0 bytes to avoid race conditions
2018/05/02 12:53:24 DEBUG : &{Untitled2.rtf (w)}: >Flush: err=<nil>
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Flush
2018/05/02 12:53:24 DEBUG : fuse: <- Release [ID=0x2 Node=0x4 Uid=501 Gid=20 Pid=23537] 0x2 fl=OpenReadOnly rfl=0 owner=0x0
2018/05/02 12:53:24 DEBUG : &{Untitled2.rtf (w)}: Release: 
2018/05/02 12:53:24 DEBUG : Untitled2.rtf: WriteFileHandle.Release closing
2018/05/02 12:53:24 DEBUG : Encrypted drive 'Media:': File to upload is small (0 bytes), uploading instead of streaming
2018/05/02 12:53:24 DEBUG : Cache remote GdriveCache:: put data at '0nlqsgnip1e7ia64fravmrk38s'
2018/05/02 12:53:24 DEBUG : : cache: expired

Elsewhere in the log, I can see fuse also generating errors for other com.apple.xyz xattr’s:

2018/05/02 12:53:24 DEBUG : fuse: <- Getxattr [ID=0x7 Node=0x4 Uid=501 Gid=20 Pid=261] "com.apple.LaunchServices.OpenWith" 0 @0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x7] Getxattr error=operation not supported

2018/05/02 12:53:24 DEBUG : fuse: <- Getxattr [ID=0x4 Node=0x4 Uid=501 Gid=20 Pid=23537] "com.apple.ResourceFork" 0 @0
2018/05/02 12:53:24 DEBUG : fuse: -> [ID=0x4] Getxattr error=operation not supported

2018/05/02 12:53:26 DEBUG : fuse: <- Getxattr [ID=0x2 Node=0x1 Uid=501 Gid=20 Pid=261] "com.apple.metadata:_kMDItemUserTags" 0 @0
2018/05/02 12:53:26 DEBUG : fuse: <- Setxattr [ID=0x4 Node=0x5 Uid=501 Gid=20 Pid=23537] "com.apple.metadata:kMDLabel_wvxa5ha2fw4qywbirsyyhwxk6m" f2dcd302419110287f9f42bf37caf639... fl=0 @0x0
2018/05/02 12:53:26 DEBUG : fuse: -> [ID=0x4] Setxattr error=operation not supported
2018/05/02 12:53:26 DEBUG : fuse: -> [ID=0x2] Getxattr error=operation not supported

Test 2: Using the cmount (not mount) build (rclone-darwin-10.6-amd64), -vv & --debug-fuse
After mounting:

The volume name forward slash suffix issue is present again (of course)
The mounted drive shows as empty (probably not reading the cache from the previously use non-cmount version?). I have a lot of files on the remote so this made me nervous as I don’t want to delete them accidentally . So I did not proceed any further with this test. If I can get this cmount binary to see my existing remote files then I’d be happy to test.

However I did test mounting with “-o volname=Media” on the cmount version, hoping to resolve the volume-name-forward-slash-suffix issue in a new way. That didn’t work and the logs show that the code just sends the -o volname option twice and the first one is taken by fuse:

Mounting with options: ["-o" "fsname=Media:" "-o" "subtype=rclone" "-o" "max_readahead=131072" "-o" "attr_timeout=1" "-o" "atomic_o_trunc" "-o" "debug" "-o" "volname=Media:" "-o" "noappledouble" "-o" "noapplexattr" "-o" "allow_other" "-o" "volname=Media"]

Of course, this also suggests that if I had tried to use -o to disable the noapplexattr option, then that would have failed in a similar manner with rclone’s initial argument for -o noapplexattr being taken by fuse instead.

So whilst I could just use the latest non-cmount binary from Test 1, does anything above clarify the root cause? Any more tests needed?

ncw · May 2, 2018, 12:09pm

Indeed!

OK, so not using the NoAppleXattr seems like it fixes the problem. Since rclone doesn’t support xattr anyway I don’t see why that shouldn’t be the default.

So actions…

remove special characters : and / from the volume name
- allow volname to be overridden? with a flag?
remove noapplexattr from the default config
- allow it to be added back with a flag? Not a problem with cmount but mount doesn’t have an -o option as it doesn’t use libfuse.
change the exit code for the xattr calls to ENOSYS to stop OSXFUSE repeatedly calling them.

Can you make a new issue on github with these things in - say “OSX mount fixes”? Then I can do a proper change against that issue. Can you put a link to the forum discussion in too.

I think it probably isn’t worth testing with cmount

jrock · May 2, 2018, 12:34pm

Thx @ncw and yes, will create the github item tomorrow, have to return to my non-rclone life for the evening!

I think that would be helpful. Eg. Call my remotes Gdrive:media->GdriveCache->GdriveCacheCrypt but mount GdriveCacheCrypt locally as “Media”.

Can do but maybe just see if it causes unforeseeable problems and deal with it then.

jrock · May 2, 2018, 1:15pm

Requested github issue has been created here:

Thanks again for helping to get mount working well with OSX everyone!

ncw · May 3, 2018, 8:57am

Thanks for making the issue - have replied there with a test binary!

jrock · May 3, 2018, 4:28pm

Thanks @ncw - will test tomorrow night and respond on Github.

blim5001 · May 5, 2018, 10:08am

The test binary works for me, and the volname option is a nice touch. Thanks @ncw