Copying files into Cache Mount on OS X

Help and Support
21

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)

22

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?

23

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.

24

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.

25

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

26

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…

27

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.

28

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