Windows rclone mount regression bug v1.43.1->v1.45

Suspected Bug
1

Hi rcloners,

Not sure if this is a bug, a config issue or a permissions issue. Any assistance very welcome!

I have been experimenting with rclone mount on a spare Windows 2012 Server:

  • Rclone v1.45
  • Gdrive -> GdriveCrypt (no backend cache)
  • rclone and Sonarr running as the “Local System” user
  • Mount command:

rclone mount GdriveDirectCrypt: F: --allow-other --bind 10.0.0.45 --dir-cache-time 72h --vfs-read-chunk-size 128M --vfs-read-chunk-size-limit off --vfs-cache-mode writes --buffer-size 0 --rc --drive-chunk-size 32M --volname Media --tpslimit 5 --fast-list --cache-db-purge --log-file C:\rclone\logs\rclone.log -vv --debug-fuse

In Windows Exporer I can copy, write, delete files on the mount without issue. I can also open a text file on the mount in Notepad, edit and then save it.

But when adding a folder within the mount to Sonarr:

  • Sonarr successfully creates it’s “sonarr_write_test.txt” file in the mount folder that it was pointed to
  • Sonarr should then delete this file from the mount and continue with it’s operations
  • Instead, the rclone mount freezes and can no longer be accessed by Sonarr, Explorer or via the command line.

Sonarr produces no logs (even in Debug and Trace modes) and with -vv --debug-fuse rclone produces the following log extract:

rclone[TID=3124]: FFFFFA800B195690: >>Create [UT---C] "\tv\90210\sonarr_write_test.txt", FILE_OVERWRITE_IF, CreateOptions=400064, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000005FC[PID=3318], DesiredAccess=120196, GrantedAccess=0, ShareAccess=1
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Open: flags=0x1
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: OpenFile: flags=O_WRONLY, perm=-rwxrwxrwx
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt: Open: flags=O_WRONLY
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt: >Open: fd=tv/90210/sonarr_write_test.txt (rw), err=<nil>
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >OpenFile: fd=tv/90210/sonarr_write_test.txt (rw), err=<nil>
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Open: errc=0, fh=0x0
rclone[TID=3124]: FFFFFA800B195690: <<Create IoStatus=0[3] UserContext=0000000000000000:00000000003409F0, GrantedAccess=120196, FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-12-16T20:29:16.295Z, LastAccessTime=2018-12-16T20:29:16.295Z, LastWriteTime=2018-12-16T20:29:16.295Z, ChangeTime=2018-12-16T20:29:16.295Z, IndexNumber=0:4cc0}
rclone[TID=3060]: FFFFFA800B195690: >>Overwrite "\tv\90210\sonarr_write_test.txt", 0000000000000000:00000000003409F0, FileAttributes=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Truncate: size=0, fh=0x0
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt(0xc000166720): Opening cached copy with flags=O_WRONLY
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Truncate: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
rclone[TID=3060]: FFFFFA800B195690: <<Overwrite IoStatus=0[0] FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:0, FileSize=0:0, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:4cc0}
rclone[TID=3060]: FFFFFA800B195690: >>Write 0000000000000000:00000000003409F0, Address=00000000003F0000, Offset=0:0, Length=127, Key=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Write: ofst=0, fh=0x0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Write: n=127
rclone[TID=3060]: FFFFFA800B195690: <<Write IoStatus=0[127] FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:4cc0}
rclone[TID=3060]: FFFFFA800B195690: >>Cleanup 0000000000000000:00000000003409F0
rclone[TID=3060]: FFFFFA800B195690: <<Cleanup IoStatus=0[0]
rclone[TID=3060]: FFFFFA800B40E8B0: >>Close 0000000000000000:00000000003409F0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Flush: fh=0x0
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt(0xc000166720): close: 
rclone[TID=3124]: FFFFFA800B195690: >>Create [UT---C] "\tv\90210\sonarr_write_test.txt", FILE_OPEN, CreateOptions=200040, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000005FC[PID=3318], DesiredAccess=10080, GrantedAccess=0, ShareAccess=7
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Open: flags=0x0
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt: Open: flags=O_RDONLY
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt: >Open: fd=tv/90210/sonarr_write_test.txt (rw), err=<nil>
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >OpenFile: fd=tv/90210/sonarr_write_test.txt (rw), err=<nil>
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Open: errc=0, fh=0x1
rclone[TID=3124]: FFFFFA800B195690: <<Create IoStatus=0[1] UserContext=0000000000000000:0000000000340840, GrantedAccess=10080, FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:4cc0}
rclone[TID=3124]: FFFFFA800B195690: >>SetInformation [Disposition] "\tv\90210\sonarr_write_test.txt", 0000000000000000:0000000000340840, Delete
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x1
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
rclone[TID=3124]: FFFFFA800B195690: <<SetInformation IoStatus=0[0] FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:4cc0}
rclone[TID=3124]: FFFFFA800B195690: >>Cleanup [Delete] "\tv\90210\sonarr_write_test.txt", 0000000000000000:0000000000340840
2018/12/17 04:52:38 DEBUG : /tv/90210/sonarr_write_test.txt: Unlink: 
2018/12/17 04:52:38 DEBUG : tv/90210/sonarr_write_test.txt: Modification times differ by -23m21.7583018s: 2018-12-17 04:52:38.0533018 +0800 CST, 2018-12-16 20:29:16.295 +0000 UTC
2018/12/17 04:52:39 INFO  : tv/90210/sonarr_write_test.txt: Copied (replaced existing)
rclone[TID=320c]: FFFFFA800D8638D0: >>Create [UT---C] "\", FILE_OPEN, CreateOptions=21, FileAttributes=10, Security=NULL, AllocationSize=0:0, AccessToken=0000000000000688[PID=13b8], DesiredAccess=100000, GrantedAccess=0, ShareAccess=0
rclone[TID=321c]: FFFFFA800AC36E10: >>Create [UT---C] "\", FILE_OPEN, CreateOptions=0, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=0000000000000664[PID=13b8], DesiredAccess=100081, GrantedAccess=0, ShareAccess=7
2018/12/17 04:53:26 DEBUG : Google drive root 'media': Checking for changes on remote
2018/12/17 04:53:26 DEBUG : Cleaning the cache
2018/12/17 04:53:27 DEBUG : tv/90210: invalidating directory cache
2018/12/17 04:54:26 DEBUG : Google drive root 'media': Checking for changes on remote
2018/12/17 04:54:26 DEBUG : Cleaning the cache
2018/12/17 04:55:26 DEBUG : Cleaning the cache
2018/12/17 04:55:26 DEBUG : Google drive root 'media': Checking for changes on remote
2018/12/17 04:56:26 DEBUG : Cleaning the cache
2018/12/17 04:56:26 DEBUG : Google drive root 'media': Checking for changes on remote
2018/12/17 04:57:26 DEBUG : Google drive root 'media': Checking for changes on remote
2018/12/17 04:57:26 DEBUG : Cleaning the cache

I can’t see any real clues here so any thoughts are very welcome.

2

I also installed the WebClient component of Windows as mentioned here.

[In Windows Server, WebClient is installed within the “Desktop Experience” role].

No change, same logs and the mount becomes inaccessible (yet the rclone service still runs).

If it helps, rclone is running as an nssm service.

3

Some more info:

  • Using the latest version of Winfsp (full install: core, developer, fuse for cygwin)
  • Tried adding --default-permissions - issue remains
  • Tried --umask 000 and 002. Unsurprisingly, rclone mount won’t start on Windows with umask.
  • Tried lauching from the command prompt instead of as a nssm service - issue remains.
  • If I run both rclone mount and Sonarr as an administrator - issue remains
  • The Sonarr test file left behind contains this text:

This file was created to verify if ‘F:\tv\90210’ is writable. It should’ve been automatically deleted. Feel free to delete it.

  • Nothing in the Windows Event Log.

I’m running out of ideas here gang. Any thoughts?

4

My last log extract included a replace of the “sonarr_write_test.txt” that was left over from a previous test. Below is a more pure log extract with a create instead of a replace…in case that helps…

rclone[TID=4cd4]: FFFFFA80080A6010: >>Create [UT—C] “\tv\90210\sonarr_write_test.txt”, FILE_OVERWRITE_IF, CreateOptions=400064, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=00000000000006B4[PID=41c], DesiredAccess=120196, GrantedAccess=0, ShareAccess=1
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=-2
2018/12/17 18:04:43 DEBUG : /tv/90210: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 18:04:43 DEBUG : /tv/90210: >Getattr: errc=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Create: flags=0x502, mode=0570
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt(0xc0000b6ae0): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt: >Open: fd=tv/90210/sonarr_write_test.txt (rw), err=
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Create: errc=0, fh=0x6
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Chown: uid=544, gid=18
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Chown: errc=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x6
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
rclone[TID=4cd4]: FFFFFA80080A6010: <<Create IoStatus=0[2] UserContext=0000000000000000:00000000002E11A0, GrantedAccess=120196, FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:0, FileSize=0:0, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:2fa}
rclone[TID=4cd4]: FFFFFA800D880460: >>Write 0000000000000000:00000000002E11A0, Address=0000000003D30000, Offset=0:0, Length=127, Key=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x6
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Write: ofst=0, fh=0x6
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Write: n=127
rclone[TID=4cd4]: FFFFFA800D880460: <<Write IoStatus=0[127] FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:2fa}
rclone[TID=4cd4]: FFFFFA8010DDFE10: >>Cleanup 0000000000000000:00000000002E11A0
rclone[TID=4cd4]: FFFFFA8010DDFE10: <<Cleanup IoStatus=0[0]
rclone[TID=4cd4]: FFFFFA800AC132B0: >>Close 0000000000000000:00000000002E11A0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Flush: fh=0x6
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt(0xc0000b6ae0): close:
rclone[TID=4ea8]: FFFFFA800D880460: >>Create [UT—C] “\tv\90210\sonarr_write_test.txt”, FILE_OPEN, CreateOptions=200040, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=000000000000057C[PID=41c], DesiredAccess=10080, GrantedAccess=0, ShareAccess=7
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Open: flags=0x0
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt: Couldn’t find file - need to transfer
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt: Open: flags=O_RDONLY
2018/12/17 18:04:43 DEBUG : tv/90210/sonarr_write_test.txt: >Open: fd=tv/90210/sonarr_write_test.txt (rw), err=
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >OpenFile: fd=tv/90210/sonarr_write_test.txt (rw), err=
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Open: errc=0, fh=0x7
rclone[TID=4ea8]: FFFFFA800D880460: <<Create IoStatus=0[1] UserContext=0000000000000000:00000000002E0F40, GrantedAccess=10080, FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:2fa}
rclone[TID=4ea8]: FFFFFA80080A6010: >>SetInformation [Disposition] “\tv\90210\sonarr_write_test.txt”, 0000000000000000:00000000002E0F40, Delete
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Getattr: fh=0x7
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: >Getattr: errc=0
rclone[TID=4ea8]: FFFFFA80080A6010: <<SetInformation IoStatus=0[0] FileInfo={FileAttributes=0, ReparseTag=0, AllocationSize=0:1000, FileSize=0:7f, CreationTime=2018-05-05T13:42:39.964Z, LastAccessTime=2018-05-05T13:42:39.964Z, LastWriteTime=2018-05-05T13:42:39.964Z, ChangeTime=2018-05-05T13:42:39.964Z, IndexNumber=0:2fa}
rclone[TID=4ea8]: FFFFFA800AC6B630: >>Cleanup [Delete] “\tv\90210\sonarr_write_test.txt”, 0000000000000000:00000000002E0F40
2018/12/17 18:04:43 DEBUG : /tv/90210/sonarr_write_test.txt: Unlink:
rclone[TID=1078]: FFFFFA801066D650: >>Create [UT—C] “\tv\90210”, FILE_OPEN, CreateOptions=20, FileAttributes=0, Security=NULL, AllocationSize=0:0, AccessToken=0000000000000678[PID=3eb4], DesiredAccess=100081, GrantedAccess=0, ShareAccess=7
2018/12/17 18:04:44 INFO : tv/90210/sonarr_write_test.txt: Copied (new)
rclone[TID=09dc]: FFFFFA800DB67530: >>Create [UT—C] “”, FILE_OPEN, CreateOptions=21, FileAttributes=10, Security=NULL, AllocationSize=0:0, AccessToken=0000000000000694[PID=3eb4], DesiredAccess=100000, GrantedAccess=0, ShareAccess=0
2018/12/17 18:05:22 DEBUG : Cleaning the cache
2018/12/17 18:05:22 DEBUG : Google drive root ‘media’: Checking for changes on remote
2018/12/17 18:05:23 DEBUG : tv/90210: invalidating directory cache
2018/12/17 18:06:22 DEBUG : Google drive root ‘media’: Checking for changes on remote
2018/12/17 18:06:22 DEBUG : Cleaning the cache

5

I also tried changing the mount’s assigned drive letter to X: (previously F:), unsurprisingly that didn’t help.

6

EDIT: See my next post - this post is wrong

OK, got it working. For anyone who follows:

  • On an Active Directory Domain-joined Windows Server 2012…
  • I could not use the “Local System” aka SYSTEM account for rclone mount and Sonarr/Radarr/Lidarr as suggested in the rclone mount docs
  • Instead I had to start them all under an Active Directory Administrative user.

Hope that helps someone.

7

So I did some more testing and have realised that the results I saw above were only circumstantial.

The real position is:

  • rclone mount and Sonarr/Radarr/Lidarr can all be running from the “Local System” aka SYSTEM account as per the rclone mount docs. This is not about permissions.
  • In rclone versions 1.44 and 1.45 I see the logs from my post above and the rclone mount becomes inaccessible.
  • In rclone version 1.43.1 there is no issue.

Could this be related to the --volname changes made in rclone-for-Windows since 1.43.1? I ask because in v1.45:

  • Before a freeze: In Windows Explorer the mount is listed as either “CryptMountNameFromConfig (X:)” [default if not using --volname] or “Volname (X:)” [if using --volname]

  • After the freeze: In Windows Explorer the mount is listed as Windows default “Local Drive (X:)”, but is inaccessible.

Might be a red herring, but it just looks like Windows is getting confused by the volname somehow.

Anyway, I have renamed this thread’s title and tagged it as a bug because it looks like this is a regression of some sort.

8

Hmm, not sure what is going on here…

It might be worth you trying the latest beta since I did fix something related to volname but I don’t think it should be related.

When the mount locks up, does it lock up completely for all access? So you can’t dir it from a cmd window for instance?

It is likely this is a deadlock…

So with the latest beta, assuming it shows the problem, can you do some debugging with rc?

What would be most useful is seeing which go-routines are active when it has locked up - you won’t have to install the go tools for that, just run --rc.

9

thx for the attention on this @ncw, appreciated.

I will sneak away from the holiday season craziness when I can and will run those tests then revert back.

thx again!

10

:smile: everyone needs an excuse for a bit of me time amid the maelstrom!

11

First time using the --rc debug function.

So to get the active go-routines I should:

Right?

12

OK, tried the latest beta, as expected it didn’t fix the issue, here are the test results:

  • I opened a new text document in notepad and tried to save it to the Mount.
  • Notepad freezes at the Save screen and the mount drive is also inaccessible to both the command prompt and Windows Explorer.
  • After restarting rclone, the mount/drive is accessible and the file shows in the mount folder it was saved/created in.
  • Browsing to http://localhost:5572/debug/pprof/goroutine?debug=1 whilst frozen gives:

goroutine profile: total 12
1 @ 0x404385 0xe4def4 0xe544af 0xe53742 0xe7cae1 0x45e931

0xe4def3 github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse._Cfunc_hostMount+0x53
_cgo_gotypes.go:466
0xe544ae github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse.(*FileSystemHost).Mount.func9+0x11e C:/gopath/src/github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse/host.go:1232
0xe53741 github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse.(*FileSystemHost).Mount+0x371 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse/host.go:1232
0xe7cae0 github.com/ncw/rclone/cmd/cmount.mount.func1+0x70 C:/gopath/src/github.com/ncw/rclone/cmd/cmount/mount.go:153

1 @ 0x40ccf2 0x444e63 0x8cb959 0x45e931
0x444e62 os/signal.signal_recv+0xa2 C:/go/src/runtime/sigqueue.go:139
0x8cb958 os/signal.loop+0x28 C:/go/src/os/signal/signal_unix.go:23

1 @ 0x432510 0x42bce0 0x42b30d 0x4b5db1 0x4b6f37 0x4b8562 0x50ae16 0x51d94f 0x6bc831 0x45e931
0x42b30c internal/poll.runtime_pollWait+0x6c C:/go/src/runtime/netpoll.go:173
0x4b5db0 internal/poll.(*pollDesc).wait+0xa0 C:/go/src/internal/poll/fd_poll_runtime.go:85
0x4b6f36 internal/poll.(*ioSrv).ExecIO+0x136 C:/go/src/internal/poll/fd_windows.go:222
0x4b8561 internal/poll.(*FD).Read+0x251 C:/go/src/internal/poll/fd_windows.go:487
0x50ae15 net.(*netFD).Read+0x55 C:/go/src/net/fd_windows.go:152
0x51d94e net.(*conn).Read+0x6e C:/go/src/net/net.go:177
0x6bc830 net/http.(*connReader).backgroundRead+0x60 C:/go/src/net/http/server.go:676

1 @ 0x432510 0x42bce0 0x42b30d 0x4b5db1 0x4b6f37 0x4b8562 0x50ae16 0x51d94f 0x79b614 0x79945f 0x799571 0x620b20 0x621044 0x624608 0x6d999c 0x537dcd 0x537f36 0x6da519 0x45e931
0x42b30c internal/poll.runtime_pollWait+0x6c C:/go/src/runtime/netpoll.go:173
0x4b5db0 internal/poll.(*pollDesc).wait+0xa0 C:/go/src/internal/poll/fd_poll_runtime.go:85
0x4b6f36 internal/poll.(*ioSrv).ExecIO+0x136 C:/go/src/internal/poll/fd_windows.go:222
0x4b8561 internal/poll.(*FD).Read+0x251 C:/go/src/internal/poll/fd_windows.go:487
0x50ae15 net.(*netFD).Read+0x55 C:/go/src/net/fd_windows.go:152
0x51d94e net.(*conn).Read+0x6e C:/go/src/net/net.go:177
0x79b613 net.Conn.Read-fm+0x53 C:/gopath/src/github.com/ncw/rclone/fs/fshttp/http.go:81
0x79945e github.com/ncw/rclone/fs/fshttp.(*timeoutConn).readOrWrite+0x4e C:/gopath/src/github.com/ncw/rclone/fs/fshttp/http.go:69
0x799570 github.com/ncw/rclone/fs/fshttp.(*timeoutConn).Read+0x90 C:/gopath/src/github.com/ncw/rclone/fs/fshttp/http.go:81
0x620b1f crypto/tls.(*block).readFromUntil+0x8f C:/go/src/crypto/tls/conn.go:492
0x621043 crypto/tls.(*Conn).readRecord+0xe3 C:/go/src/crypto/tls/conn.go:593
0x624607 crypto/tls.(*Conn).Read+0xf7 C:/go/src/crypto/tls/conn.go:1145
0x6d999b net/http.(*persistConn).Read+0x7b C:/go/src/net/http/transport.go:1497
0x537dcc bufio.(*Reader).fill+0x10c C:/go/src/bufio/bufio.go:100
0x537f35 bufio.(*Reader).Peek+0x45 C:/go/src/bufio/bufio.go:132
0x6da518 net/http.(*persistConn).readLoop+0x1a8 C:/go/src/net/http/transport.go:1645

1 @ 0x432510 0x42bce0 0x42b30d 0x4b5db1 0x4b6f37 0x4ba109 0x4ba3a2 0x50b3d1 0x5262a5 0x5249be 0x6e8583 0x6c5ee6 0x785c75 0x45e931
0x42b30c internal/poll.runtime_pollWait+0x6c C:/go/src/runtime/netpoll.go:173
0x4b5db0 internal/poll.(*pollDesc).wait+0xa0 C:/go/src/internal/poll/fd_poll_runtime.go:85
0x4b6f36 internal/poll.(*ioSrv).ExecIO+0x136 C:/go/src/internal/poll/fd_windows.go:222
0x4ba108 internal/poll.(*FD).acceptOne+0xa8 C:/go/src/internal/poll/fd_windows.go:796
0x4ba3a1 internal/poll.(*FD).Accept+0x141 C:/go/src/internal/poll/fd_windows.go:830
0x50b3d0 net.(*netFD).accept+0x80 C:/go/src/net/fd_windows.go:193
0x5262a4 net.(*TCPListener).accept+0x34 C:/go/src/net/tcpsock_posix.go:139
0x5249bd net.(*TCPListener).Accept+0x4d C:/go/src/net/tcpsock.go:260
0x6c5ee5 net/http.(*Server).Serve+0x235 C:/go/src/net/http/server.go:2826
0x785c74 github.com/ncw/rclone/cmd/serve/httplib.(*Server).Serve.func1+0x434 C:/gopath/src/github.com/ncw/rclone/cmd/serve/httplib/httplib.go:245

1 @ 0x432510 0x4325ca 0x442dba 0x442ab4 0x467ec6 0xe5ff71 0xe66137 0xe66b72 0xe78867 0xe51a45 0xe4eedc 0x45cb42 0x404739 0x4044eb 0x45e1a2 0x45e931
0x442ab3 sync.runtime_SemacquireMutex+0x43 C:/go/src/runtime/sema.go:71
0x467ec5 sync.(*Mutex).Lock+0x105 C:/go/src/sync/mutex.go:134
0xe5ff70 github.com/ncw/rclone/vfs.(*File).setObject+0x40 C:/gopath/src/github.com/ncw/rclone/vfs/file.go:333
0xe66136 github.com/ncw/rclone/vfs.(*RWFileHandle).close+0x746 C:/gopath/src/github.com/ncw/rclone/vfs/read_write.go:311
0xe66b71 github.com/ncw/rclone/vfs.(*RWFileHandle).Release+0x121 C:/gopath/src/github.com/ncw/rclone/vfs/read_write.go:371
0xe78866 github.com/ncw/rclone/cmd/cmount.(*FS).Release+0x236 C:/gopath/src/github.com/ncw/rclone/cmd/cmount/fs.go:391
0xe51a44 github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse.hostRelease+0xb4 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse/host.go:838
0xe4eedb github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse._cgoexpwrap_b0480560eb0d_hostRelease+0x3b _cgo_gotypes.go:762
0x45cb41 runtime.call32+0x41 C:/go/src/runtime/asm_amd64.s:522
0x404738 runtime.cgocallbackg1+0x1a8 C:/go/src/runtime/cgocall.go:316
0x4044ea runtime.cgocallbackg+0xea C:/go/src/runtime/cgocall.go:194
0x45e1a1 runtime.cgocallback_gofunc+0xb1 C:/go/src/runtime/asm_amd64.s:775

1 @ 0x432510 0x4325ca 0x442dba 0x442ab4 0x467ec6 0xe6093d 0xe5d1c0 0xe78aaf 0xe50c47 0xe4e4f2 0x45cb42 0x404739 0x4044eb 0x45e1a2 0x45e931
0x442ab3 sync.runtime_SemacquireMutex+0x43 C:/go/src/runtime/sema.go:71
0x467ec5 sync.(*Mutex).Lock+0x105 C:/go/src/sync/mutex.go:134
0xe6093c github.com/ncw/rclone/vfs.(*File).Remove+0x8c C:/gopath/src/github.com/ncw/rclone/vfs/file.go:445
0xe5d1bf github.com/ncw/rclone/vfs.(*Dir).RemoveName+0x11f C:/gopath/src/github.com/ncw/rclone/vfs/dir.go:540
0xe78aae github.com/ncw/rclone/cmd/cmount.(*FS).Unlink+0x1ae C:/gopath/src/github.com/ncw/rclone/cmd/cmount/fs.go:401
0xe50c46 github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse.hostUnlink+0xa6 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse/host.go:710
0xe4e4f1 github.com/ncw/rclone/vendor/github.com/billziss-gh/cgofuse/fuse._cgoexpwrap_b0480560eb0d_hostUnlink+0x31 _cgo_gotypes.go:593
0x45cb41 runtime.call32+0x41 C:/go/src/runtime/asm_amd64.s:522
0x404738 runtime.cgocallbackg1+0x1a8 C:/go/src/runtime/cgocall.go:316
0x4044ea runtime.cgocallbackg+0xea C:/go/src/runtime/cgocall.go:194
0x45e1a1 runtime.cgocallback_gofunc+0xb1 C:/go/src/runtime/asm_amd64.s:775

1 @ 0x432510 0x4421b2 0x6dbafa 0x45e931
0x6dbaf9 net/http.(*persistConn).writeLoop+0x119 C:/go/src/net/http/transport.go:1885

1 @ 0x432510 0x4421b2 0xa20730 0x45e931
0xa2072f github.com/ncw/rclone/backend/drive.(*Fs).ChangeNotify.func1+0x19f C:/gopath/src/github.com/ncw/rclone/backend/drive/drive.go:2070

1 @ 0x432510 0x4421b2 0xe59a46 0x45e931
0xe59a45 github.com/ncw/rclone/vfs.(*cache).cleaner+0x145 C:/gopath/src/github.com/ncw/rclone/vfs/cache.go:429

1 @ 0x432510 0x4421b2 0xe7c983 0xe74e3e 0xe2b4c3 0xe2c074 0xe2bd42 0xe47e7d 0xf223c7 0x432137 0x45e931
0xe7c982 github.com/ncw/rclone/cmd/cmount.Mount+0x1a2 C:/gopath/src/github.com/ncw/rclone/cmd/cmount/mount.go:226
0xe74e3d github.com/ncw/rclone/cmd/mountlib.NewMountCommand.func1+0x25d C:/gopath/src/github.com/ncw/rclone/cmd/mountlib/mount.go:256
0xe2b4c2 github.com/ncw/rclone/vendor/github.com/spf13/cobra.(*Command).execute+0x2d2 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/spf13/cobra/command.go:766
0xe2c073 github.com/ncw/rclone/vendor/github.com/spf13/cobra.(*Command).ExecuteC+0x303 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/spf13/cobra/command.go:852
0xe2bd41 github.com/ncw/rclone/vendor/github.com/spf13/cobra.(*Command).Execute+0x31 C:/gopath/src/github.com/ncw/rclone/vendor/github.com/spf13/cobra/command.go:800
0xe47e7c github.com/ncw/rclone/cmd.Main+0x4c C:/gopath/src/github.com/ncw/rclone/cmd/cmd.go:482
0xf223c6 main.main+0x26 C:/gopath/src/github.com/ncw/rclone/rclone.go:13
0x432136 runtime.main+0x206 C:/go/src/runtime/proc.go:201

1 @ 0x7743cf 0x7741c7 0x770b7b 0x77d0d7 0x77d9aa 0x6c2d7b 0x6c4a4e 0x6c5a62 0x6c1dad 0x45e931
0x7743ce runtime/pprof.writeRuntimeProfile+0x9e C:/go/src/runtime/pprof/pprof.go:707
0x7741c6 runtime/pprof.writeGoroutine+0xa6 C:/go/src/runtime/pprof/pprof.go:669
0x770b7a runtime/pprof.(*Profile).WriteTo+0x3ea C:/go/src/runtime/pprof/pprof.go:328
0x77d0d6 net/http/pprof.handler.ServeHTTP+0x216 C:/go/src/net/http/pprof/pprof.go:245
0x77d9a9 net/http/pprof.Index+0x729 C:/go/src/net/http/pprof/pprof.go:268
0x6c2d7a net/http.HandlerFunc.ServeHTTP+0x4a C:/go/src/net/http/server.go:1964
0x6c4a4d net/http.(*ServeMux).ServeHTTP+0x12d C:/go/src/net/http/server.go:2361
0x6c5a61 net/http.serverHandler.ServeHTTP+0xb1 C:/go/src/net/http/server.go:2741
0x6c1dac net/http.(*conn).serve+0x64c C:/go/src/net/http/server.go:1847

  • And the -vv logs show:

2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /: Statfs:
2018/12/20 23:50:39 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:264767177824 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=-2
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Opendir:
2018/12/20 23:50:39 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : /: >OpenFile: fd=/ ®, err=
2018/12/20 23:50:39 DEBUG : /: >Opendir: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /: Releasedir: fh=0x1
2018/12/20 23:50:39 DEBUG : /: >Releasedir: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Create: flags=0x502, mode=0700
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt: Open: flags=O_RDWR|O_CREATE|O_EXCL
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt(0xc000054e40): Opening cached copy with flags=O_RDWR|O_CREATE|O_EXCL
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt: >Open: fd=save_open_file_to_mount_test.txt (rw), err=
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Create: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Flush: fh=0x1
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt(0xc000054e40): RWFileHandle.Flush ignoring flush on unwritten handle
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Flush: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Release: fh=0x1
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt(0xc000054e40): RWFileHandle.Release closing
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt(0xc000054e40): close:
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0xFFFFFFFFFFFFFFFF
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Open: flags=0x0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt: Open: flags=O_RDONLY
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt: Couldn’t find file - need to transfer
2018/12/20 23:50:39 DEBUG : save_open_file_to_mount_test.txt: >Open: fd=save_open_file_to_mount_test.txt (rw), err=
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >OpenFile: fd=save_open_file_to_mount_test.txt (rw), err=
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Open: errc=0, fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Getattr: fh=0x1
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: >Getattr: errc=0
2018/12/20 23:50:39 DEBUG : /save_open_file_to_mount_test.txt: Unlink:
2018/12/20 23:50:41 INFO : save_open_file_to_mount_test.txt: Copied (new)
2018/12/20 23:50:53 DEBUG : Google drive root ‘media’: Checking for changes on remote
2018/12/20 23:50:53 DEBUG : Cleaning the cache
2018/12/20 23:51:53 DEBUG : Google drive root ‘media’: Checking for changes on remote
2018/12/20 23:51:53 DEBUG : Cleaning the cache

That get us anywhere?

13

Thank you for the logs.

I think this problem may well be related to the other one you posted: `--vfs-cache-mode writes` upload expected behaviour?

It does indeed look like a deadlock, it looks like file remove deadlocking against setting the time…

Can you please make a new issue on github about this please?

I will investigate further!

14

Yes I was wondering if they might be related as well. Thx again for looking into it. I will post the github issue tomorrow (it’s very late here!).

1 Like
15

Github issue created.