Debug log says host.Unmount failed on normal Ctrl-C exit on Windows

[albertony]

What is the problem you are having with rclone?

(Probably just a minor, "cosmetic", issue, or maybe not an issue at all, but could also be something worth digging more into..)

The debug log contains "host.Unmount failed" on normal Ctrl-C exit on Windows:

The service rclone has been stopped.
2021/01/25 14:35:59 DEBUG : Google drive root '': Destroy:
2021/01/25 14:35:59 DEBUG : Google drive root '': >Destroy:
2021/01/25 14:35:59 DEBUG : Calling host.Unmount
2021/01/25 14:35:59 DEBUG : host.Unmount failed

Tried to debug it, but reached a dead end... Can see that on Ctrl-C then cgofuse.fuse.host.hostDestroy is being called (*), setting host.fuse=nil, before rclone.cmd.mountlib.mount.Mount --> rclone.cmd.cmount.unmount --> cgofuse.fuse.host.Unmount, which returns false because host.fuse is nil, with the result that rclone logs unmount failed.

The doc on cgofuse.fuse.host.Unmount states:

Unmount may be called at any time after the Init() method has been called and before the Destroy() method has been called.

So obviously in my case this requirement is being "broken": Unmount is being called after Destroy. But cgofuse's Unmount detects this and just aborts. No harm done. The mountpoint gets properly removed. Calling unmount seems unnecessary in this case. Could therefore just leave it as is, or perhaps a minor change in the log message to something less "pessimistic". But since this is documented as incorrect usage, my reason for reporting this in the first place, was a feeling that this should be digged a bit more into in case it may lead to other issues in future.

Questions:

• (*) How is hostDestroy called? Ctrl-C handling logic in native code inside cgofuse/WinFsp?
• Should the Ctrl-C have been caught by rclone's if atexit.Signalled() test, and reported "Not calling host.Unmount as signal received"?

What is your rclone version (output from rclone version)

rclone v1.53.4

• os/arch: windows/amd64
• go version: go1.15.6

Same in v1.53.0, v1.52.3

Which OS you are using and how many bits (e.g. Windows 7, 64 bit)

Windows, 64 bit.

Which cloud storage system are you using? (e.g. Google Drive)

Google Drive

The command you were trying to run (e.g. rclone copy /tmp remote:tmp)

rclone mount google: X: -vv

A log from the command with the -vv flag (e.g. output from rclone -vv copy /tmp remote:tmp)

[ncw]

Questions:

• (*) How is hostDestroy called? Ctrl-C handling logic in native code inside cgofuse/WinFsp?

It is called by cgofuse I think under non windows and WinFSP under Windows.

• Should the Ctrl-C have been caught by rclone's if atexit.Signalled() test, and reported "Not calling host.Unmount as signal received"?

I think what is happening is that the C registered atexit handler is winning the race to get notified here. The Go atexit handler hasn't been called yet.

This code gets used in multiple OSes so needs more testing obviously!

                     mount      cmount
Windows       -              x
Linux             x             x
macOS         -              x

While investigating this, I managed to fix the occasional unmount failure with linux problem.

I don't think this will fix your issue with Windows, but it may help - can you give it a go?

v1.54.0-beta.5088.4e5dd8644.fix-4957-atexit on branch fix-4957-atexit (uploaded in 15-30 mins)

With windows, we could re-arrange the test to see if the mountpoint disappears to provide a definitive - this got unmounted signal.

[albertony]

I think what is happening is that the C registered atexit handler is winning the race to get notified here. The Go atexit handler hasn't been called yet.

That makes sense, yes.

I don't think this will fix your issue with Windows, but it may help - can you give it a go?

You were correct - no change. :)

[albertony]

I find it hard to follow the steps between rclone, cgofuse and winfsp, with its mix of golang and c, and without any prior knowledge of fuse, and I fear it would be too time consuming at this point to dig enough into it too get a good understanding (as much as I'd like to)..

I take the chance of sharing some thoughts anyway, based on reading this https://github.com/billziss-gh/winfsp/issues/47 and some other sources:

If we can trust that WinFsp gets the Ctrl-C event (first), then I guess it will do its shutdown before informing rclone (via Destroyed), and there is nothing more rclone can or should do as part of the shutdown?

It seems to me that winfsp is designed to be quite bullet proof regarding cleanup. If the statement "killing the process from the debugger should clean up all associated resources" is true, then I guess it should not be of any difference if we managed to call unmount or not when rclone is about to exit anyways?

In my case, cmd.cmount.fs.Destroy is being called (from cgofuse.fuse.host.hostDestroy, with the statement host.fsop.Destroy()), before the unmount attempt. So then rclone should be able to know it is terminating and that it is too late to try host.Unmount, and could use this information to avoid trying unmount? E.g. something like this, if fs had an Destroyed() boolean:

if atexit.Signalled() {
    // If we have received a signal then FUSE will be shutting down already
    fs.Debugf(nil, "Not calling host.Unmount as signal received")
    umountOK = true
} else if fsys.Destroyed() {
    fs.Debugf(nil, "Not calling host.Unmount as the file system has already been destroyed")
    umountOK = true
} else {
    fs.Debugf(nil, "Calling host.Unmount")
    umountOK = host.Unmount()
}

In any case:

we could re-arrange the test to see if the mountpoint disappears to provide a definitive - this got unmounted signal.

..should probably be done, I agree.

[ncw]

I find it hard to follow the steps between rclone, cgofuse and winfsp, with its mix of golang and c, and without any prior knowledge of fuse, and I fear it would be too time consuming at this point to dig enough into it too get a good understanding (as much as I'd like to)..

It is confusing!

I take the chance of sharing some thoughts anyway, based on reading this billziss-gh/winfsp#47 and some other sources:

If we can trust that WinFsp gets the Ctrl-C event (first), then I guess it will do its shutdown before informing rclone (via Destroyed), and there is nothing more rclone can or should do as part of the shutdown?

Yes that is correct. Though I'm not sure the behaviour on Windows and Linux is the same.

It seems to me that winfsp is designed to be quite bullet proof regarding cleanup.

Bill is definitely a bullet-proof developer - I'd agree with that!

If the statement "killing the process from the debugger should clean up all associated resources" is true, then I guess it should not be of any difference if we managed to call unmount or not when rclone is about to exit anyways?

Again, I think that depends on Windows vs Linux.

In my case, cmd.cmount.fs.Destroy is being called (from cgofuse.fuse.host.hostDestroy, with the statement host.fsop.Destroy()), before the unmount attempt. So then rclone should be able to know it is terminating and that it is too late to try host.Unmount, and could use this information to avoid trying unmount? E.g. something like this, if fs had an Destroyed() boolean:

if atexit.Signalled() {
  // If we have received a signal then FUSE will be shutting down already
  fs.Debugf(nil, "Not calling host.Unmount as signal received")
  umountOK = true
} else if fsys.Destroyed() {
  fs.Debugf(nil, "Not calling host.Unmount as the file system has already been destroyed")
  umountOK = true
} else {
  fs.Debugf(nil, "Calling host.Unmount")
  umountOK = host.Unmount()
}

That is a great idea

I had a go with that here

v1.54.0-beta.5112.20be44229.fix-cmount-umount on branch fix-cmount-umount (uploaded in 15-30 mins)

Note under linux Destroy doesn't get called it seems.

In any case:

we could re-arrange the test to see if the mountpoint disappears to provide a definitive - this got unmounted signal.

..should probably be done, I agree.

[albertony]

I had a go with that

Great. Tested OK on Windows 10 x64, with disk and network mount.

DEBUG : Not calling host.Unmount as mount already Destroyed
DEBUG : Unmounted successfully

[ncw]

Thanks for testing. I've merged this to master now which means it will be in the latest beta in 15-30 mins and released in v1.54