Windows mount polling not recognising all changes made by another box

What is the problem you are having with rclone?

I have an issue where some changes made to my Gdrive are not being picked up by polling in a Windows mount, when the changes are made from another box.

Scenario: I have an unlimited Gdrive which I access from three different boxes. The first is a mount on a shared seedbox, running things like Sonarr, Radarr etc, and this is where the majority of updates are done to the mount. The second is an Ubuntu VPS where I run Plex so access is largely read only (although the mount is read/write, same as the seedbox). Thirdly, I have a mount on my Windows 10 PC for ad-hoc access, and it's with this that I am having the problem.

What happens is, any changes made to the mount on the Seedbox are being picked up ok by the VPS, but not always by the Windows mount - if files are created in the seedbox, they don't always appear on the Windows mount, files deleted don't disapear and so on. However, all changes made on the seedbox are picked up on the VPS (and by Plex). Also, after doing further testing, it seems I only get this problem when I have folders under folders. So if I have a structure such has "topfolder/subfolder", Windows correctly recognises the changes and updates the directory cache, but if I have another level of folders, such as "topfolder/subfolder/subsubfolder" it doesn't pick up any changes that have been made via the seedbox.

I've created a test mount and have reproduced the issue. I am simply creating a new empty file on the seedbox mount, two folders deep, which appears on the VPS but not on Windows. There is an interesting part in the debug logs that may indicate what's happening. On the VPS, when polling detects the change, I see:

2020/05/27 12:50:20 DEBUG : Google drive root 'Encrypted': Checking for changes on remote
2020/05/27 12:50:20 DEBUG : : changeNotify: relativePath="Sub1/Subsub1/emptyfile1", type=3
2020/05/27 12:50:20 DEBUG : Sub1/Subsub1: invalidating directory cache
2020/05/27 12:50:20 DEBUG : : >changeNotify:

However, on the Windows mount I see:

2020/05/27 12:50:29 DEBUG : Google drive root 'Encrypted': Checking for changes on remote
2020/05/27 12:50:29 DEBUG : : changeNotify: relativePath="Sub1/Subsub1/emptyfile1", type=3
2020/05/27 12:50:29 DEBUG : : >changeNotify:

Note the missing line: - Sub1/Subsub1: invalidating directory cache

So it looks like on Windows that any changes to folders more than one deep are being recognised but the directory cache isn't being invalidated and hence why I can't see the changes in Windows Explorer or using DIR on the mounted drive.

Is this a bug?

What is your rclone version (output from rclone version)

rclone v1.51.0

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

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

Seedbox - some flavour of Debian, 64bit
VPS - Ubuntu 18.04 64 bit
Windows - 10, 64 bit

Which cloud storage system are you using? (eg Google Drive)

GSuite

The command you were trying to run (eg rclone copy /tmp remote:tmp)

Seedbox mount: /home18/renzz27/rclonenew/rclone mount Gsuite-Crypt: /home18/renzz27/files/Test-mount/ --dir-cache-time 24h --allow-other --drive-chunk-size 512M --vfs-cache-mode writes --log-file /home18/renzz27/files/rclone-test-mount.log --user-agent Laurie --buffer-size 256M --config /home18/renzz27/files/rclone-test.conf -vv --poll-interval 15s

VPS mount: rclone mount Gsuite-Crypt: /home/lauried/files/Test-mount/ --dir-cache-time 24h --allow-other --drive-chunk-size 512M --vfs-cache-mode writes --log-file /home/lauried/files/rclone-test-mount.log --user-agent Laurie --buffer-size 256M --config /home/lauried/files/rclone-test.conf -vv --poll-interval 15s

Windows mount: c:\video\rclone\rclone.exe mount Gsuite-Crypt: x: --dir-cache-time 24h --drive-chunk-size 512M --vfs-cache-mode writes --log-file c:\video\rclone\rclone-test-mount.log --user-agent Laurie --buffer-size 256M --config C:\Users\renzz\.config\rclone\rclone-test.conf -vv --poll-interval 15s

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

A zip with debug logs from all three servers is at https://wsi.li/RNe0YY4OEjZkdH/2582009

My test rclone.conf is:

[Gsuite]
type = drive
client_id = xxxxxx
client_secret = xxxxxx
scope = drive
root_folder_id = 0AIBwCvABIKkBUk9PVA
service_account_file =
token = xxxxxx

[Gsuite-Crypt]
type = crypt
remote = Gsuite:Encrypted
filename_encryption = standard
password = xxxxxx
password2 = xxxxxx

It doesn't seem you are using trash:

So not sure that applies.

Can you recreate the issue with --dump bodies and we see the request and what the issue might be?

Ok, recreated with --dump bodies - the logs are at https://wetransfer.com/downloads/69e1d56b59d54cff2a5f3b933c90702920200527124444/2de0ddf53c3372e0dc9e4c4f4fc84c8f20200527124506/645b29

I don't think this is a polling problem because you can see in the Windows log it recognises the new file. I think it's the code not invalidating the directory cache when the folder structure is deeper than one level,

FYI, I just tried this using the new 1.52 for Windows and still have the same issue.

I've put the log at https://wetransfer.com/downloads/f59cd4acc176fec8f37579f681000de020200528083042/966901be582aa26cf7cf2685619fdb5720200528083103/7107f4

There are two reasons that it might not print Sub1/Subsub1: invalidating directory cache firstly that directory might not be in the cache and secondly it might have already expired.

So can you try the same test, but make sure you list (with DIR in the command line) the Sub1/Subsub1 directory before making the change to the file.

Then listing it again.

If you could report back on whether you see the Sub1/Subsub1: invalidating directory cache this time that would be great!

Thanks

With the folder empty, doing a DIR shows, as expected:

C:\Windows\System32>dir x:\Sub1\Subsub1
Volume in drive X is Gsuite-Crypt
Volume Serial Number is B6BC-DCB8

Directory of x:\Sub1\Subsub1

27/05/2020 12:40 .
26/05/2020 13:41 ..
0 File(s) 0 bytes
2 Dir(s) 1,125,899,906,842,624 bytes free

I then created the file "emptyfile1" on the seedbox, but a DIR on Windows still shows it empty:

C:\Windows\System32>dir x:\Sub1\Subsub1
Volume in drive X is Gsuite-Crypt
Volume Serial Number is B6BC-DCB8

Directory of x:\Sub1\Subsub1

27/05/2020 12:40 .
26/05/2020 13:41 ..
0 File(s) 0 bytes
2 Dir(s) 1,125,899,906,842,624 bytes free

In the log on WIndows, there's no sign of the "invalidating directory cache" entry (this is with dump bodies still enabled):

2020/05/27 13:40:20 DEBUG : Google drive root 'Encrypted': Checking for changes on remote
2020/05/27 13:40:20 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/05/27 13:40:20 DEBUG : HTTP REQUEST (req 0xc00026c400)
2020/05/27 13:40:20 DEBUG : GET /drive/v3/changes?alt=json&fields=nextPageToken%2CnewStartPageToken%2Cchanges%28fileId%2Cfile%28name%2Cparents%2CmimeType%29%29&includeItemsFromAllDrives=true&pageSize=1000&pageToken=296312&prettyPrint=false&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: Laurie
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.13.0 gdcl/20191026
Accept-Encoding: gzip

2020/05/27 13:40:20 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/05/27 13:40:20 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/05/27 13:40:20 DEBUG : HTTP RESPONSE (req 0xc00026c400)
2020/05/27 13:40:20 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-27=":443"; ma=2592000,h3-25=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Wed, 27 May 2020 12:40:20 GMT
Expires: Wed, 27 May 2020 12:40:20 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

dc
{"newStartPageToken":"296313","changes":[{"fileId":"15yiMHyuNxzhVDXDVvL1Itl6vHLhSOABG","file":{"name":"1vkciposeienq8dn49jdmr13q4","mimeType":"application/octet-stream","parents":["1SfDBdo0_iIocZc3a_KPozeUQjXxznRtm"]}}]}
0

2020/05/27 13:40:20 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/05/27 13:40:20 DEBUG : : changeNotify: relativePath="Sub1/Subsub1/emptyfile1", type=3
2020/05/27 13:40:20 DEBUG : : >changeNotify:
2020/05/27 13:40:31 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/05/27 13:40:31 DEBUG : /: >Getattr: errc=0

I'm wracking my brain trying to think of anything which would cause this on Windows Vs Linux.

Ideas might be case sensitivity... Is the case of all the paths consistent?

Is there a chance you might have a duplicate directory? Can you try rclone dedupe on the drive? A duplicate directory might explain it.

If neither of those rings a bell then I'll send you an rclone riddled with debug statements!

There are no duplicates as far as I can see:

C:\Video\rclone>rclone dedupe Gsuite-Crypt: --config C:\Users\renzz.config\rclone\rclone-test.conf --dry-run -vv
2020/05/29 08:52:37 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "dedupe" "Gsuite-Crypt:" "--config" "C:\Users\renzz\.config\rclone\rclone-test.conf" "--dry-run" "-vv"]
2020/05/29 08:52:37 DEBUG : Using config file from "C:\Users\renzz\.config\rclone\rclone-test.conf"
2020/05/29 08:52:38 INFO : Encrypted drive 'Gsuite-Crypt:': Looking for duplicates using interactive mode.
2020/05/29 08:52:40 DEBUG : 6 go routines active
C:\Video\rclone>

I changed the folders to use all lowercase but it still behaves the same:

2020/05/29 09:13:59 DEBUG : Google drive root 'Encrypted': Checking for changes on remote
2020/05/29 09:13:59 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/05/29 09:13:59 DEBUG : HTTP REQUEST (req 0xc001786300)
2020/05/29 09:13:59 DEBUG : GET /drive/v3/changes?alt=json&fields=nextPageToken%2CnewStartPageToken%2Cchanges%28fileId%2Cfile%28name%2Cparents%2CmimeType%29%29&includeItemsFromAllDrives=true&pageSize=1000&pageToken=296389&prettyPrint=false&supportsAllDrives=true HTTP/1.1
Host: www.googleapis.com
User-Agent: Laurie
Authorization: XXXX
X-Goog-Api-Client: gl-go/1.14.3 gdcl/20200410
Accept-Encoding: gzip

2020/05/29 09:13:59 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2020/05/29 09:13:59 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/05/29 09:13:59 DEBUG : HTTP RESPONSE (req 0xc001786300)
2020/05/29 09:13:59 DEBUG : HTTP/1.1 200 OK
Transfer-Encoding: chunked
Alt-Svc: h3-27=":443"; ma=2592000,h3-25=":443"; ma=2592000,h3-T050=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q049=":443"; ma=2592000,h3-Q048=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
Cache-Control: private, max-age=0, must-revalidate, no-transform
Content-Security-Policy: frame-ancestors 'self'
Content-Type: application/json; charset=UTF-8
Date: Fri, 29 May 2020 08:14:00 GMT
Expires: Fri, 29 May 2020 08:14:00 GMT
Server: GSE
Vary: Origin
Vary: X-Origin
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-Xss-Protection: 1; mode=block

dc
{"newStartPageToken":"296391","changes":[{"fileId":"1LeR3worlhX-uaUJel2HwZ75rOnSUoMnI","file":{"name":"1vkciposeienq8dn49jdmr13q4","mimeType":"application/octet-stream","parents":["1JzevFxzhv_LUF_T9qTKrb0RHnbfjqgKo"]}}]}
0

2020/05/29 09:13:59 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/05/29 09:13:59 DEBUG : : changeNotify: relativePath="sub1/subsub1/emptyfile1", type=3
2020/05/29 09:13:59 DEBUG : : >changeNotify:
2020/05/29 09:14:09 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2020/05/29 09:14:09 DEBUG : /: >Getattr: errc=0

I'm happy to do more debugging so let me know when you have the debug version available.

Thanks!

what version of winfsp are you running?

I'm running Winfsp 2020

@ncw Hi Nick, did you get a chance to knock up a debug version for this problem?

Cheers

Give this a go! It should show what is going on hopefully...

https://beta.rclone.org/branch/v1.52.0-021-gf1a5539f-fix-win-changes-beta/ (uploaded in 15-30 mins)

Thanks Nick.

The log file is at https://wetransfer.com/downloads/9ab78f6125382b696455b08dfdc4ced220200602150618/d7a5beaaa6bb734042f51c067739a51f20200602150635/2b61a8

The interesting bit is:

2020/06/02 16:04:27 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/06/02 16:04:27 DEBUG : : changeNotify: relativePath="sub1/subsub1/newempty1", type=3
2020/06/02 16:04:27 DEBUG : : invalidateDir: absPath="sub1\\subsub1"
2020/06/02 16:04:27 DEBUG : : >invalidateDir: 
2020/06/02 16:04:27 DEBUG : : >changeNotify: 
2020/06/02 16:04:34 DEBUG : /sub1: Getattr: fh=0xFFFFFFFFFFFFFFFF

Hope this helps!

It does :smiley: Some backslashes have crept into the path somehow...

I see confusion between OS paths and internal (Unix paths) rclone uses...

Can you have a go with this? I've left the extra debug in...

https://beta.rclone.org/branch/v1.52.0-022-gb0222b88-fix-win-changes-beta/ (uploaded in 15-30 mins)

That seems to have fixed it! :slight_smile:

Full log is here:

Interesting bit in the log is:

2020/06/02 20:03:29 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2020/06/02 20:03:29 DEBUG : : changeNotify: relativePath="sub1/subsub1/emptyfile1", type=3
2020/06/02 20:03:29 DEBUG : : invalidateDir: absPath="sub1/subsub1"
2020/06/02 20:03:29 DEBUG : sub1/subsub1: invalidateDir: checking dir 2020-06-02 20:03:09.2840688 +0100 BST m=+11.452373501 is zero false
2020/06/02 20:03:29 DEBUG : sub1/subsub1: invalidating directory cache
2020/06/02 20:03:29 DEBUG : : >invalidateDir: 
2020/06/02 20:03:29 DEBUG : : >changeNotify: 
2020/06/02 20:03:33 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF

I guess this fix will find it's way into the next beta.

Many thanks for fixing it!

Thks !! it works for me too !

And thanks for this post :slight_smile:

Thanks for testing.

I can't believe I made that mistake and I haven't noticed it before!

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

This topic was automatically closed 3 days after the last reply. New replies are no longer allowed.