OSX mount command appears to be broken in latest beta

I have just download the latest beta for OSX but when trying to mount a google drive rclone just exits.

I have tried with the working settings that I was using with the previous betas (for the OSX fixes) and tried with just a very basic mount command, both exhibit the same behaviour.

I can’t see anything useful in the rclone log, (this is the log with -vvv)

rclone-141-048 mount gcache: ~/_mounts/gDrive-rclone-cache -vvv
2018/05/12 07:24:37 DEBUG : rclone: Version "v1.41-048-gd022c81dβ" starting with parameters ["/usr/local/bin/rclone-141-048" "mount" "gcache:" "/Users/admin/_mounts/gDrive-rclone-cache" "-vvv"]
2018/05/12 07:24:37 DEBUG : Using config file from "/Users/admin/.rclone.conf"
2018/05/12 07:24:37 DEBUG : gcache: wrapped gSuite2: at root 
2018/05/12 07:24:37 INFO  : gcache: Cache DB path: /Users/admin/Library/Caches/rclone/cache-backend/gcache.db
2018/05/12 07:24:37 INFO  : gcache: Cache chunk path: /Users/admin/Library/Caches/rclone/cache-backend/gcache
2018/05/12 07:24:37 INFO  : gcache: Chunk Memory: true
2018/05/12 07:24:37 INFO  : gcache: Chunk Size: 4M
2018/05/12 07:24:37 INFO  : gcache: Chunk Total Size: 10G
2018/05/12 07:24:37 INFO  : gcache: Chunk Clean Interval: 1m0s
2018/05/12 07:24:37 INFO  : gcache: Workers: 4
2018/05/12 07:24:37 INFO  : gcache: File Age: 1h0m0s
2018/05/12 07:24:37 DEBUG : Adding path "cache/expire" to remote control registry
2018/05/12 07:24:37 DEBUG : Adding path "cache/stats" to remote control registry
2018/05/12 07:24:37 INFO  : Cache remote gcache:: Modify window is 1ms
2018/05/12 07:24:37 DEBUG : Cache remote gcache:: Mounting on "/Users/admin/_mounts/gDrive-rclone-cache"
2018/05/12 07:24:37 DEBUG : Cache remote gcache:: subscribing to ChangeNotify
2018/05/12 07:24:37 DEBUG : Adding path "vfs/forget" to remote control registry
2018/05/12 07:24:37 DEBUG : : Root: 
2018/05/12 07:24:37 DEBUG : : >Root: node=/, err=<nil>
2018/05/12 07:24:37 DEBUG : : Statfs: 
2018/05/12 07:24:37 DEBUG : /: Attr: 
2018/05/12 07:24:37 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/05/12 07:24:37 DEBUG : : Statfs: 
2018/05/12 07:24:37 DEBUG : : Statfs: 
2018/05/12 07:24:37 INFO  : Signal received: %!s(<nil>)
2018/05/12 07:24:37 DEBUG : Cache remote gcache:: Services stopped
2018/05/12 07:24:37 INFO  : Exiting...

But in the console I see

osxfuse: failed to update vfsstat (err=5)

Not sure if that is relevant.

Going back through a few of the betas and the command still works in 1.41-046-gc4ecb32b and 1.41.047-gcdde8fa7

So does look like something was broken in just the very latest beta (1.41-048-gd022c81d)

Hmm, this is from https://github.com/ncw/rclone/pull/2304

I’ll see if @B4dM4n knows what is up…

I’m not sure why this happens, but I added a check to prevent the early exit.

Could you check if v1.41-049-g6791cf7d (uploaded soon) fixes the issue for you?

Thanks, I did see that and thought it might be something to do with that :wink:

I have just cloned the repository to my mac and if i switch to commit ad02d1b and build then the mount command works

@B4dM4n, just saw the change and pulled it into my local copy and yes that seems to have fixed it.

Thanks for the speedy fix

And at least now I can build it on my mac, which will hopefully get rid of the random net/http TLS handshake timeout errors that sometimes happened when unmounting and then remounting the drive.

Used to happen with plexdrive as well, and the solution there was to build it on a mac

Hmm, interesting…

I could (with a bit of effort) arrange for the builds to be native macOS builds using the travis infrastructure.

Do you think that would be worth doing?

It might be nice for those less technically minded, (Now I can build it myself, don’t put it too high on your todo list on my account), and I am not sure how many people it impacts, as jrock has not mentioned it.

For some reason, it was happening almost every time on my VM, I would connect once then unmount and attempt a remount straight away and it would fail with a
net/http: TLS handshake timeout
error

That was when I remembered this had been an issue with plexdrive on OSX

If I rebooted the VM it would mount just fine again, and I think if I left it for a while before trying to remount it would connect.

But since building the latest beta on my the Mac the error seems to have gone away, and can unmount and remount with no problems.

I don’t know what the cause is, and it does seem to be a bit random. It might be something to do with the internet connection, or the route to google (or wherever you are connecting to). Although saying that, it does not really explain why it works after a reboot, as it does not take very long to reboot the VM

Thanks for your thoughts. I made an issue about that here: https://github.com/ncw/rclone/issues/2309

Can you reproduce these? If so can you share a log?

I’ll see what I can do when I get home.

Ok, so I download the latest beta to my VM, unmounted my drive and tried to remount using the same parameters.

This is the error:

2018/05/14 18:22:06 DEBUG : rclone: Version "v1.41-058-ge62d2fd3β" starting with parameters ...
2018/05/14 18:22:06 DEBUG : Using config file from "/Users/blim/.rclone.conf"
2018/05/14 18:22:06 DEBUG : gcache: wrapped gSuite2: at root 
2018/05/14 18:22:06 INFO  : gcache: Cache DB path: /Users/blim/_rclone_caches/gDrive-rclone-cache-caches/cacheDB/gcache.db
2018/05/14 18:22:06 INFO  : gcache: Cache chunk path: /Users/blim/_rclone_caches/gDrive-rclone-cache-caches/cacheChunks/gcache
2018/05/14 18:22:06 INFO  : gcache: Chunk Memory: true
2018/05/14 18:22:06 INFO  : gcache: Chunk Size: 4M
2018/05/14 18:22:06 INFO  : gcache: Chunk Total Size: 10G
2018/05/14 18:22:06 INFO  : gcache: Chunk Clean Interval: 1m0s
2018/05/14 18:22:06 INFO  : gcache: Workers: 8
2018/05/14 18:22:06 INFO  : gcache: File Age: 10h0m0s
2018/05/14 18:22:06 INFO  : gcache: Cache Writes: enabled
2018/05/14 18:22:06 INFO  : gcache: Upload Temp Rest Time: 2h0m0s
2018/05/14 18:22:06 INFO  : gcache: Upload Temp FS: /Users/blim/_mounts/_rclone_uploads/gDrive-rclone-cache-uploads
2018/05/14 18:22:06 NOTICE: Serving remote control on http://127.0.0.1:5572/
2018/05/14 18:22:06 DEBUG : Adding path "cache/expire" to remote control registry
2018/05/14 18:22:06 DEBUG : Adding path "cache/stats" to remote control registry
2018/05/14 18:22:06 INFO  : Cache remote gcache:: Modify window is 1ms
2018/05/14 18:22:06 DEBUG : Cache remote gcache:: Mounting on "/Users/blim/_mounts/gDrive-rclone-cache"
2018/05/14 18:22:06 DEBUG : Cache remote gcache:: subscribing to ChangeNotify
2018/05/14 18:22:06 DEBUG : vfs cache root is "/Users/blim/Library/Caches/rclone/vfs/gcache"
2018/05/14 18:22:06 DEBUG : Adding path "vfs/forget" to remote control registry
2018/05/14 18:22:06 DEBUG : : Root: 
2018/05/14 18:22:06 DEBUG : : >Root: node=/, err=<nil>
2018/05/14 18:22:06 DEBUG : : Statfs: 
2018/05/14 18:22:06 DEBUG : /: Attr: 
2018/05/14 18:22:06 DEBUG : /: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2018/05/14 18:22:06 DEBUG : : Statfs: 
2018/05/14 18:22:06 DEBUG : : Statfs: 
2018/05/14 18:23:06 DEBUG : Cache remote gcache:: starting cleanup
2018/05/14 18:23:06 DEBUG : pacer: Rate limited, sleeping for 1.115485645s (1 consecutive low level retries)
2018/05/14 18:23:06 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&supportsTeamDrives=false: net/http: TLS handshake timeout)
2018/05/14 18:23:07 DEBUG : pacer: Rate limited, sleeping for 2.406917158s (2 consecutive low level retries)
2018/05/14 18:23:07 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/v3/about?alt=json&fields=storageQuota: net/http: TLS handshake timeout)
2018/05/14 18:24:06 DEBUG : Cache remote gcache:: starting cleanup
2018/05/14 18:24:06 DEBUG : pacer: Rate limited, sleeping for 4.18190685s (3 consecutive low level retries)
2018/05/14 18:24:06 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&supportsTeamDrives=false: net/http: TLS handshake timeout)
2018/05/14 18:24:08 DEBUG : pacer: Rate limited, sleeping for 8.865660866s (4 consecutive low level retries)
2018/05/14 18:24:08 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/v3/about?alt=json&fields=storageQuota: net/http: TLS handshake timeout)
2018/05/14 18:24:08 DEBUG : pacer: Resetting sleep to minimum 10ms on success
2018/05/14 18:24:08 DEBUG : Google drive root '': Checking for changes on remote
2018/05/14 18:24:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:229243310506 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/14 18:24:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:229243310506 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/14 18:24:11 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:229243310506 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2018/05/14 18:24:11 DEBUG : rclone: Version "v1.41-058-ge62d2fd3β" finishing with parameters ... 
2018/05/14 18:24:11 DEBUG : Google drive root '': All changes were processed. Waiting for more.
2018/05/14 18:24:12 DEBUG : Cache remote gcache:: Services stopped

I took out the parameters, as I don’t think these make any difference but if you need them, let me know

So then I ran umount to unmount the drive (as when it fails it leaves an unusable mount), and then ran the same mount command using the beta version that I built on my mac and it mounts successfully.

I guess the question is when you say remount - what did you do? Can you say the exact sequence of events?

Of course…

So I had my drive mounted in my Mac VM.

I ejected the mounted drive from the finder.

Right Click on the drive -> Eject

Back to the Terminal.
I attempted to run the same mount command, but this time using the downloaded beta version of rclone rather than the version I built on the mac.

At that point it generated the error message that I posted above

If I ran the mount command it would show there was a mount, but it was not useable.

If I try to cd to the mounted directory and do a ls I get

ls: .: Device not configured

so I ran umount to unmount it.

Finally ran the rclone mount command again using the version of rclone I had built on the Mac and that mounted successfully

So which versions of rclone does that procedure work with? Or does it just depend on whether you used the --daemon flag or not?

I have never used the --daemon flag

afaik, doing this: Right Click on the drive -> Eject using the finder

is the same as running umount from the command line.

Sorry if that’s confusing things

Ah OK!

Did this used to work, or is this a new problem?

osxfuse uses the umount command rather than than the fusermount command that you use with fuse on linux.

I don’t think the net/http TLS handshake timeout errors are a new problem, in that I have seen them with various different versions of rclone, and also with plexdrive.

But in normal usage you do not see it very often, as un mounting and then re mounting the drive straight away is not something you do very often, unless you are testing things.

When you said

The rclone mount appeared to stop normally but you said it required an additional unmount command afterwards.,

Is that something that happens every time?

Yep after you see the net/http timeout errors in the log file

2018/05/14 18:23:06 DEBUG : Cache remote gcache:: starting cleanup
2018/05/14 18:23:06 DEBUG : pacer: Rate limited, sleeping for 1.115485645s (1 consecutive low level retries)
2018/05/14 18:23:06 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&supportsTeamDrives=false: net/http: TLS handshake timeout)
2018/05/14 18:23:07 DEBUG : pacer: Rate limited, sleeping for 2.406917158s (2 consecutive low level retries)
2018/05/14 18:23:07 DEBUG : pacer: low level retry 1/10 (error Get https://www.googleapis.com/drive/v3/about?alt=json&fields=storageQuota: net/http: TLS handshake timeout)
2018/05/14 18:24:06 DEBUG : Cache remote gcache:: starting cleanup
2018/05/14 18:24:06 DEBUG : pacer: Rate limited, sleeping for 4.18190685s (3 consecutive low level retries)
2018/05/14 18:24:06 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/v3/changes/startPageToken?alt=json&supportsTeamDrives=false: net/http: TLS handshake timeout)
2018/05/14 18:24:08 DEBUG : pacer: Rate limited, sleeping for 8.865660866s (4 consecutive low level retries)
2018/05/14 18:24:08 DEBUG : pacer: low level retry 2/10 (error Get https://www.googleapis.com/drive/v3/about?alt=json&fields=storageQuota: net/http: TLS handshake timeout)
2018/05/14 18:24:08 DEBUG : pacer: Resetting sleep to minimum 10ms on success

and then you see

2018/05/14 18:24:11 DEBUG : rclone: Version "v1.41-058-ge62d2fd3β" finishing with parameters ... 
2018/05/14 18:24:11 DEBUG : Google drive root '': All changes were processed. Waiting for more.
2018/05/14 18:24:12 DEBUG : Cache remote gcache:: Services stopped

So it looks like mount seemed to stop normally

but the osx mount command (not the rclone mount command ) lists it as a mount, I can cd into the mount, but an ‘ls’ command responds with

ls: .: Device not configured

at that point i need to run umount to remove it

And yep, that happens every time after I see the net/http timeout errors

I see - thanks for explaining.

In that log, it looks like the command succeeded eventually

So I’m not sure why the mount would be unmountable at that point. But it might be something else which is causing that problem.

But if you use the native compiled rclone you don’t get this problem - is that correct?