Copying files into Cache Mount on OS X

I think I am have to going to have to some more methodical testing…

I only tried one file without the cache, so I will try mounting it again without cache and try a few more files.

Will let you know how I get on

1 Like

Ok, some test results. (problems do seem to happen with cache and without)

I mounted without cache:

Tried copying a 550MB video file (making sure it had no additional attributes) to the mount via Finder

Result: Finder started copy and rclone started to upload chunks, Finder then reported the error

Rclone continued to upload, then rclone sort of stopped:

2018/04/11 18:30:40 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells.mp4: Sending chunk 553648128 length 5667792
2018/04/11 18:30:44 INFO : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells.mp4: Copied (new)
2018/04/11 18:30:44 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells.mp4: transferred to remote
2018/04/11 18:30:44 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells.mp4(0xc4202e2540): >close: err=
2018/04/11 18:30:44 DEBUG : &{uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells.mp4 (rw)}: >Flush: err=
2018/04/11 18:30:44 DEBUG : rclone: Version “v1.40-031-ge42cee5eβ” finishing with parameters ["/usr/local/bin/rclone-14beta" “mount” “gSuite:” “/mounts/gDrive/” “–allow-other” “–vfs-cache-mode” “writes” “-vv”]

but mount still shows:
gSuite: on /mounts/gDrive (osxfuse, nodev, nosuid, synchronous, mounted by admin)

If I try to cd to a dir on the mount I get “Device not configured” Error

Manually unmounted the volume and remounted… then on to test 2

So next, I removed the uploaded file from my google drive and tried to copy the file using cp

and that gave me a Socket is not connected error, but looking at the rclone log it is still transferring the file
rclone finished uploading the file, but again it ended again:
rclone: Version “v1.40-031-ge42cee5eβ” finishing with parameters…

I downloaded the uploaded file from my gdrive and it appears to be the same size as the original and does play, so looks like the file is ok (just checked and the MD5 is the same for both files)

So next I tried mounting the cache with the same setting as the previous mount but adding settings
–cache-tmp-upload-path
and
–cache-tmp-wait-time 5m

So copying the file via the finder gets me the permissions error
and nothing gets copied to dir I specified with --cache-tmp-upload-path

Using cp the file is copied without issue and I can see it in dir specified with --cache-tmp-upload-path

And after the 5 min I can now see rclone is uploading the file… and now is done and I can see the file in my gdrive.
I downloaded it and the md5 of both files match.

I guess there are not many mac users who need to write to their mounts :wink:

I might try adding --debug-fuse to see if that holds any clues?

That is very strange. rclone did just exit but didn’t print anything in the log!

It was an orderly shutdown though so it is as if the mount just exited. You might find --debug-fuse prints more info here.

The fact it is consistent will mean it should be easy to track it down anyway!

BTW are you using a recent version of OSXFUSE?

That looks like a separate issue to the stopping one.

The integration tests run on travis run the mount through the test suite on OSX so it should work!

Unfortunately I don’t have an OSX machine which is going to make this hard to debug :frowning:

I’ll see if I can get it running in VirtualBox…

I am using the latest version of osxfuse (3.7.1) the pkg download from osxfuse.github.io rather than installing using homebrew or macports.

I also use sshfs to mount directories from some of my servers, so I did try copying the same file into one of my sshfs mounts using the finder and this worked without issues.
Both the rclone mount and the sshfs mounts look the same:
(osxfuse, nodev, nosuid, synchronous, mounted by admin)

I did try with --debug-fuse last night and did not spot anything obvious, but it is very noisy, and I am not really sure what I am looking for, so I will give it another go later.

Thanks - I’m particularly interested in why the mount just stopped without cache so the end of the log would be most interesting.

Hi,

Just tried the regular mount (no cache) with fuse-debug and tried copying the file again using the finder.

Got the permissions error as expected, and from the end of the log we have:

2018/04/12 12:03:55 INFO : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells WEBDL-720p ipl.mp4: Copied (new)
2018/04/12 12:03:55 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells WEBDL-720p ipl.mp4: transferred to remote
2018/04/12 12:03:55 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells WEBDL-720p ipl.mp4(0xc4213ba240): >close: err=
2018/04/12 12:03:55 DEBUG : &{uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells WEBDL-720p ipl.mp4 (rw)}: >Flush: err=
2018/04/12 12:03:55 DEBUG : fuse: -> [ID=0x4] Flush
2018/04/12 12:03:55 DEBUG : fuse: kernel write error: error=“socket is not connected” stack=
goroutine 4221 [running]:
github.com/ncw/rclone/vendor/bazil.org/fuse.stack(0x1ce0920, 0xc4258f0180)
/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/debug.go:9 +0x74
github.com/ncw/rclone/vendor/bazil.org/fuse.(*Conn).respond(0xc42033c4e0, 0xc4258f0170, 0x10, 0x10)
/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:1113 +0x96
github.com/ncw/rclone/vendor/bazil.org/fuse.(*Header).respond(0xc425cccaf0, 0xc4258f0170, 0x10, 0x10)
/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:313 +0x59
github.com/ncw/rclone/vendor/bazil.org/fuse.(*FlushRequest).Respond(0xc425cccaf0)
/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:2091 +0x6d
github.com/ncw/rclone/vendor/bazil.org/fuse/fs.(*Server).handleRequest(0xc420132240, 0x1ce8e80, 0xc425d84a40, 0x1cdd700, 0xc4201717c0, 0xc420204700, 0x1ce6f80, 0xc425cccaf0, 0xc425ef7ef8, 0x0, …)
/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fs/serve.go:1287 +0x2b7
2018/04/12 12:03:55 DEBUG : rclone: Version “v1.40-065-ge82452ceβ” finishing with parameters…

Don’t know if that helps, if you need any more of the log, let me know.

(oh and I updated to the latest beta, just in case that made any difference)

That is helpful thanks.

What appeared to happen is that rclone via the fuse library it used tried to respond to the kernel but the kernel closed the socket. Which is weird!

Are there any kernel logs you can look at to see if there is a message from the kernel?

It would be interesting if you could give this binary a try… It is built with the native libraries and will support an alternate libfuse based mount called cmount

https://833-17803236-gh.circle-artifacts.com/0/tmp/rclone.dist/rclone-darwin-10.6-amd64

so rclone cmount ... instead of rclone mount .... That may (or may not) shed some light on the issue!

BTW which version of macOS are you running?

Am running 10.12.6 (Sierra)
(I have not updated to High Sierra yet)

I will dig through the OSX logs to see what I can find.

I will give that version a go a bit later and report back what happens.

Thanks

Just tried that binary and cmount will mount the drive but it shows as empty.
(tried with and without sudo, just in case, same result no files or folders show up in the mount)

:frowning:

That makes me wonder if there is something wrong with your OSXFUSE install… Have you tried re-installing it?

How about different versions of OSXFUSE?

I did wonder that, but if there is something wrong with my OSXFUSE install I would have expected to see problems when copying to my sshfs mounts.

But I will try re-installs and different versions this evening.

I just tried installing osxfuse on my Mac at work which is running a much older OSX, 10.10.5

And that exhibits the same issues…

Trying to find the kernel logs, I found this:

2018-04-12 18:25:13.071794+0100 localhost kernel[0]: process rclone[18130] caught waking the CPU 45003 times over ~72 seconds, averaging 617 wakes / second and violating a limit of 45000 wakes over 300 seconds.

and

2018-04-12 18:31:25.816999+0100 localhost kernel[0]: (osxfuse) osxfuse: filehandle_get: failed for David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells WEBDL-720p ipl.mp4 (type=0, err=2, caller=)
2018-04-12 18:31:25.817008+0100 localhost kernel[0]: (osxfuse) osxfuse: filehandle_get failed in open (type=0, err=2)

That message looks kind of ominous! I can’t find any more stuff about it though. Did rclone get killed or signalled or squashed in some way at that point?

Can you disable whatever makes that message?

I am afraid I don’t know what makes that message, I wonder if it could be when the mount drops / rclone exits after trying to copy a file.

I have just mounted the drive and am going to leave it mounted for a few hours and see if the message re-appears.

If it does not, I will then try and copy a file and see if that causes the error.

It would be interesting to know if you get that message about the time the mount drops.

What that message looks like is the OS saying “rclone you are too busy”. Now what the kernel does after that I don’t know - it may kill rclone, or throttle it either of which could cause the mount to drop.

Ok, so I left my gdrive mounted all day and did not see the kernel message

Tried to copy the same file I have been using for testing, and yep the kernel message reappeared at around the same time that the finder showed the message about being unable to copy the file and the mount disconnected
(although mount still shows the drive as mounted, but trying to cd into the drive gives me a ‘Device not configured message’ so I need to umount the drive and remount to regain access.)

And I do see the see the same message in the rclone log:

2018/04/13 18:26:58 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells  WEBDL-720p ipl.mp4: transferred to remote
2018/04/13 18:26:58 DEBUG : uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells  WEBDL-720p ipl.mp4(0xc4245941e0): >close: err=<nil>
2018/04/13 18:26:58 DEBUG : &{uploads/David Attenboroughs Natural Curiosities - s04e05 - Incredible Shells  WEBDL-720p ipl.mp4 (rw)}: >Flush: err=<nil>
2018/04/13 18:26:58 DEBUG : fuse: -> [ID=0x5] Flush
2018/04/13 18:26:58 DEBUG : fuse: kernel write error: error="socket is not connected" stack=
goroutine 12600 [running]:
github.com/ncw/rclone/vendor/bazil.org/fuse.stack(0x1ce0920, 0xc4202b2410)
	/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/debug.go:9 +0x74
github.com/ncw/rclone/vendor/bazil.org/fuse.(*Conn).respond(0xc42009e540, 0xc4202b2400, 0x10, 0x10)
	/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:1113 +0x96
github.com/ncw/rclone/vendor/bazil.org/fuse.(*Header).respond(0xc4281755e0, 0xc4202b2400, 0x10, 0x10)
	/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:313 +0x59
github.com/ncw/rclone/vendor/bazil.org/fuse.(*FlushRequest).Respond(0xc4281755e0)
	/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fuse.go:2091 +0x6d
github.com/ncw/rclone/vendor/bazil.org/fuse/fs.(*Server).handleRequest(0xc42014c240, 0x1ce8e80, 0xc4281c5880, 0x1cdd700, 0xc4202ec040, 0xc421406240, 0x1ce6f80, 0xc4281755e0, 0xc428323ef8, 0x0, ...)
	/home/travis/gopath/src/github.com/ncw/rclone/vendor/bazil.org/fuse/fs/serve.go:1287 +0x2b
2018/04/13 18:26:58 DEBUG : rclone: Version "v1.40-065-ge82452ceβ" finishing with parameters...

as before

What I don’t know is how to work out if it drops the mount first and then we get the kernel message or if the kernel message happens and then it drops the mount.

I think it may be the latter (but its only a guess) as I don’t get the error above from rclone until rclone has finished transferring the file to gdrive.

But sadly I seem to be struggling to find any useful error messages to actually pinpoint what’s going wrong

The kernel messages you posted before had a timestamp - can you compare the new ones with the times in the rclone log?

Do you think it might be worth turning off all the power/energy saving features of macOS and trying again? That message is something about power saving…

Hello @blim5001 and @ncw:

Just got that exact kernel message here, also on Mac OSX High Sierra but with rclone serve restic, not rclone mount.

The exact message shown by dmesg was:
process rclone[91967] caught waking the CPU 45001 times over ~253 seconds, averaging 177 wakes / second and violating a limit of 45000 wakes over 300 seconds.

When I check on the process with ps auwx, it has not been killed by the OS and indeed seems to be happily running along:
root 91967 0.0 0.1 4557216 86048 ?? S 9:17PM 2:11.65 rclone serve restic --stdio --b2-hard-delete --drive-use-trash=false --rc --rc-addr localhost:5582 --rc-no-auth REDACTED1:REDACTED2/REDACTED3

In fact, except for some slowness (which I attribute to restic and not to rclone), the underlying restic backup operation seem to be progressing normally -- I just detected that message and wondered what the heck it's about, and then searched and found this topic.

Does anyone know what the heck it means? I'm far from being an expert on OSX... :-/

Cheers,
-- Durval.

Please open a new topic rather than necro bumping an old topic.