Saving files causes wrong modified time to be set for a few seconds on webdav mount with Bitrix24

owlthematrixblitzar · March 1, 2023, 12:45pm

What is the problem you are having with rclone?

I am currently trying to modify Rclone so that Bitrix24 webdav can be used as a backend. So far I have made two modifications to the source of 1.61.1 to adapt to Bitrix24 quirks and built a dev version on Ubuntu and on windows:

Bitrix24 does not conform to the webdav RFC regarding trailing slashes when moving folders so in /backend/webdav/webdav.go on line 1110 for the dirMove function i changed
```
 	"Destination": addSlash(destinationURL.String()), 
```

to

		"Destination": destinationURL.String(),

Bitrix24 also changes it's behavior by reading the useragent of the webdav client, so in /fs/config.go on line 169 i changed the useragent to windows webdav:
```
 	c.UserAgent = "Microsoft-WebDAV-MiniRedir/6.1.7601"
```

With these modifications everything seems to work correctly and i can mount, change and move files/folders, but there is an issue when saving files.

When any modification is made to a file and saved then temporarily for a few seconds the file modified date is set to Sat Sep 4 12:00:00 AM UTC 1999

After a few seconds it then changes to the correct modified time. This happens on both a windows and linux build.
I suspect this has something to do with the VFS but i can't seem to find the cause. I have tried multiple command line parameters like --refresh-times , --no-modtime , --no-update-modtime, --use-server-modtime and --vfs-fast-fingerprint. None of them fix this specific issue

The same issue shows on a windows build and this causes programs like excel to think that the file was changed when it wasn't, for example :

open a excel file on the mount, make a change, save
-- ok until now, but now the modified date has been set to 1999 --
make a new change and save again, now excel complains that someone else might have changed the file and if i want to save a copy or overwrite, even though only my user has access to this file. This happens even if I wait a few minutes before saving again.

Example from linux: (the date commands are run around less than a second apart:

user@ubuntu:~$ echo sometext > /bitrixmount/user/test/test.txt
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Sat Sep  4 12:00:00 AM UTC 1999
user@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Wed Mar  1 11:37:42 AM UTC 2023

Run the command 'rclone version' and share the full output of the command.

rclone v1.61.1-DEV
- os/version: ubuntu 22.04 (64 bit)
- os/kernel: 5.15.0-60-generic (x86_64)
- os/type: linux
- os/arch: amd64
- go/version: go1.18.1
- go/linking: dynamic
- go/tags: none

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

Self hosted Bitrix24

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

sudo rclone -vv mount buser: /bitrixmount/user --allow-other --uid 1001 --vfs-cache-mode full

The rclone config contents with secrets removed.

[buser]
type = webdav
url = https:[SECRET]
vendor = other
user = [SECRET]
pass = [SECRET]

A log from the command with the `-vv` flag

2023/03/01 11:37:28 DEBUG : rclone: Version "v1.61.1-DEV" starting with parameters ["rclone" "-vv" "mount" "user:" "/bitrixmount/user" "--allow-other" "--uid" "1001" "--vfs-cache-mode" "full"]
2023/03/01 11:37:28 DEBUG : Creating backend with remote "user:"
2023/03/01 11:37:28 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/03/01 11:37:28 DEBUG : found headers: 
2023/03/01 11:37:28 INFO  : webdav root '': poll-interval is not supported by this remote
2023/03/01 11:37:28 DEBUG : vfs cache: root is "/root/.cache/rclone"
2023/03/01 11:37:28 DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/user"
2023/03/01 11:37:28 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/user"
2023/03/01 11:37:28 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/user/"
2023/03/01 11:37:28 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfs/user/" to be canonical "/root/.cache/rclone/vfs/user"
2023/03/01 11:37:28 DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/user/"
2023/03/01 11:37:28 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfsMeta/user/" to be canonical "/root/.cache/rclone/vfsMeta/user"
2023/03/01 11:37:28 DEBUG : webdav root '': Mounting on "/bitrixmount/user"
2023/03/01 11:37:28 INFO  : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)
2023/03/01 11:37:28 DEBUG : : Root: 
2023/03/01 11:37:28 DEBUG : : >Root: node=/, err=<nil>
2023/03/01 11:37:36 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:36 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:36 DEBUG : test/: Attr: 
2023/03/01 11:37:36 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:36 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:37 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:37 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: Open: flags=OpenWriteOnly
2023/03/01 11:37:37 DEBUG : test/test.txt: Open: flags=O_WRONLY
2023/03/01 11:37:37 DEBUG : test/test.txt: newRWFileHandle: 
2023/03/01 11:37:37 DEBUG : test/test.txt: >newRWFileHandle: err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: >Open: fd=test/test.txt (rw), err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: >Open: fh=&{test/test.txt (rw)}, err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: Setattr: a=Setattr [ID=0xc Node=0x3 Uid=1000 Gid=1000 Pid=117721] size=0 handle=INVALID-0x0 lockowner
2023/03/01 11:37:37 DEBUG : test/test.txt: Truncating 1 file handles
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): openPending: 
2023/03/01 11:37:37 DEBUG : test/test.txt: vfs cache: checking remote fingerprint "9" against cached fingerprint ""
2023/03/01 11:37:37 DEBUG : test/test.txt: vfs cache: truncate to size=9
2023/03/01 11:37:37 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): >openPending: err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: vfs cache: truncate to size=0
2023/03/01 11:37:37 DEBUG : test/test.txt: >Setattr: err=<nil>
2023/03/01 11:37:37 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:37 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): RWFileHandle.Flush
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: Write: len=9, offset=0
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): _writeAt: size=9, off=0
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): >_writeAt: n=9, err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: >Write: written=9, err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): RWFileHandle.Flush
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: Release: 
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): RWFileHandle.Release
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): close: 
2023/03/01 11:37:37 DEBUG : vfs cache: looking for range={Pos:0 Size:9} in [{Pos:0 Size:9}] - present true
2023/03/01 11:37:37 DEBUG : test/test.txt: vfs cache: setting modification time to 2023-03-01 11:37:37.029817898 +0000 UTC m=+8.289212836
2023/03/01 11:37:37 INFO  : test/test.txt: vfs cache: queuing for upload in 5s
2023/03/01 11:37:37 DEBUG : test/test.txt(0xc000b02040): >close: err=<nil>
2023/03/01 11:37:37 DEBUG : &{test/test.txt (rw)}: >Release: err=<nil>
2023/03/01 11:37:38 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:38 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:38 DEBUG : test/: Attr: 
2023/03/01 11:37:38 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:38 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:38 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:38 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:38 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:39 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:39 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:39 DEBUG : test/: Attr: 
2023/03/01 11:37:39 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:39 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:39 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:39 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:39 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:40 DEBUG : : Statfs: 
2023/03/01 11:37:40 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/01 11:37:41 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:41 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:41 DEBUG : test/: Attr: 
2023/03/01 11:37:41 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:41 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:41 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:41 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:41 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:42 DEBUG : test/test.txt: vfs cache: starting upload
2023/03/01 11:37:42 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:42 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:42 DEBUG : test/: Attr: 
2023/03/01 11:37:42 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:42 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:42 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:42 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:42 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:42 INFO  : test/test.txt: Copied (replaced existing)
2023/03/01 11:37:42 DEBUG : test/test.txt: vfs cache: writeback object to VFS layer
2023/03/01 11:37:42 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/01 11:37:42 INFO  : test/test.txt: vfs cache: upload succeeded try #1
2023/03/01 11:37:43 DEBUG : /: Lookup: name="test"
2023/03/01 11:37:43 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/01 11:37:43 DEBUG : test/: Attr: 
2023/03/01 11:37:43 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/01 11:37:43 DEBUG : test/: Lookup: name="test.txt"
2023/03/01 11:37:43 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/01 11:37:43 DEBUG : test/test.txt: Attr: 
2023/03/01 11:37:43 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=9 mode=-rw-r--r--, err=<nil>
2023/03/01 11:37:45 DEBUG : : Statfs: 
2023/03/01 11:37:45 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
^C2023/03/01 11:37:49 INFO  : Signal received: interrupt
2023/03/01 11:37:49 DEBUG : vfs cache: cleaner exiting
2023/03/01 11:37:49 ERROR : /bitrixmount/user: Unmounted rclone mount
2023/03/01 11:37:49 DEBUG : rclone: Version "v1.61.1-DEV" finishing with parameters ["rclone" "-vv" "mount" "user:" "/bitrixmount/user" "--allow-other" "--uid" "1001" "--vfs-cache-mode" "full"]
2023/03/01 11:37:49 INFO  : Exiting...

ncw · March 2, 2023, 7:52pm

owlthematrixblitzar:

Bitrix24 does not conform to the webdav RFC regarding trailing slashes when moving folders so in /backend/webdav/webdav.go on line 1110 for the dirMove function i changed

OK. That could be covered with a provider quirk.

Ewww! What does it do differently?

That is strange!

I would add some debugs to print the value of Object.modTime in the webdav backend on the Object.ModTime method and trace from there.

owlthematrixblitzar · March 2, 2023, 8:43pm

Hi Nick,

Thanks for taking the time to look into this.

According to Cryptomator can access webdav and create vault but can not open it in bitrix24 cloud. · Issue #234 · cryptomator/android · GitHub it looks like they disable GET responses for file downloads unless the useragent is on a whitelist

I'm not really a programmer, figuring this out by googling old forum posts and github issues, but from some googling i assume i should add something like this anywhere i see a "return o.modTime" in the webdav.go file?

	fs.Debugf(nil, "Bitrix debug omodtime", o.modtime)
	return o.modTime

ncw · March 2, 2023, 10:13pm

Yes that looks good, give that a go.

owlthematrixblitzar · March 3, 2023, 10:11am

Hi Nick,

No luck, o.modtime sets the correct date but that is not visible in the filesystem. I added a debug message for the following two functions:

func (o *Object) ModTime(ctx context.Context) time.Time
and
func (o *Object) setMetaData(info *api.Prop) (err error)

here are just the debug strings (the time difference is probably the timezone mismatch between the server and rclone client):

2023/03/03 09:24:43 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 08:59:55 +0000 GMT)
2023/03/03 09:24:43 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-03 08:59:55 +0000 GMT)
2023/03/03 09:24:48 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 09:24:48 +0000 GMT)
2023/03/03 09:24:49 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-03 09:24:48 +0000 GMT)

And the full log

2023/03/03 09:24:34 DEBUG : rclone: Version "v1.61.1-DEV" starting with parameters ["rclone" "-vv" "mount" "buser:" "/bitrixmount/user" "--allow-other" "--uid" "1001" "--vfs-cache-mode" "full"]
2023/03/03 09:24:34 DEBUG : Creating backend with remote "buser:"
2023/03/03 09:24:34 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/03/03 09:24:34 DEBUG : found headers: 
2023/03/03 09:24:34 INFO  : webdav root '': poll-interval is not supported by this remote
2023/03/03 09:24:34 DEBUG : vfs cache: root is "/root/.cache/rclone"
2023/03/03 09:24:34 DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/buser"
2023/03/03 09:24:34 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/buser"
2023/03/03 09:24:34 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/buser/"
2023/03/03 09:24:34 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfs/buser/" to be canonical "/root/.cache/rclone/vfs/buser"
2023/03/03 09:24:34 DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/buser/"
2023/03/03 09:24:34 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfsMeta/buser/" to be canonical "/root/.cache/rclone/vfsMeta/buser"
2023/03/03 09:24:34 DEBUG : webdav root '': Mounting on "/bitrixmount/user"
2023/03/03 09:24:34 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/test.txt not removed, freed 0 bytes
2023/03/03 09:24:34 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 24 (was 24)
2023/03/03 09:24:34 DEBUG : : Root: 
2023/03/03 09:24:34 DEBUG : : >Root: node=/, err=<nil>
2023/03/03 09:24:41 DEBUG : : Statfs: 
2023/03/03 09:24:42 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 09:24:42 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:43 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:43 DEBUG : test/: Attr: 
2023/03/03 09:24:43 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:43 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:43 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 08:59:55 +0000 GMT)
2023/03/03 09:24:43 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:43 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-03 08:59:55 +0000 GMT)
2023/03/03 09:24:43 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=24 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: Open: flags=OpenWriteOnly
2023/03/03 09:24:43 DEBUG : test/test.txt: Open: flags=O_WRONLY
2023/03/03 09:24:43 DEBUG : test/test.txt: newRWFileHandle: 
2023/03/03 09:24:43 DEBUG : test/test.txt: >newRWFileHandle: err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: >Open: fd=test/test.txt (rw), err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: >Open: fh=&{test/test.txt (rw)}, err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: Setattr: a=Setattr [ID=0xe Node=0x3 Uid=1000 Gid=1000 Pid=260965] size=0 handle=INVALID-0x0 lockowner
2023/03/03 09:24:43 DEBUG : test/test.txt: Truncating 1 file handles
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): openPending: 
2023/03/03 09:24:43 DEBUG : test/test.txt: vfs cache: checking remote fingerprint "24" against cached fingerprint "24"
2023/03/03 09:24:43 DEBUG : test/test.txt: vfs cache: truncate to size=24 (not needed as size correct)
2023/03/03 09:24:43 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): >openPending: err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: vfs cache: truncate to size=0
2023/03/03 09:24:43 DEBUG : test/test.txt: >Setattr: err=<nil>
2023/03/03 09:24:43 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:43 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): RWFileHandle.Flush
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: Write: len=30, offset=0
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): _writeAt: size=30, off=0
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): >_writeAt: n=30, err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: >Write: written=30, err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): RWFileHandle.Flush
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: Release: 
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): RWFileHandle.Release
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): close: 
2023/03/03 09:24:43 DEBUG : vfs cache: looking for range={Pos:0 Size:30} in [{Pos:0 Size:30}] - present true
2023/03/03 09:24:43 DEBUG : test/test.txt: vfs cache: setting modification time to 2023-03-03 09:24:43.167566045 +0000 UTC m=+9.110602210
2023/03/03 09:24:43 INFO  : test/test.txt: vfs cache: queuing for upload in 5s
2023/03/03 09:24:43 DEBUG : test/test.txt(0xc0005583c0): >close: err=<nil>
2023/03/03 09:24:43 DEBUG : &{test/test.txt (rw)}: >Release: err=<nil>
2023/03/03 09:24:44 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:44 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:44 DEBUG : test/: Attr: 
2023/03/03 09:24:44 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:44 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:44 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:44 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:44 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=30 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:45 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:45 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:45 DEBUG : test/: Attr: 
2023/03/03 09:24:45 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:45 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:45 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:45 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:45 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=30 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:46 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:46 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:46 DEBUG : test/: Attr: 
2023/03/03 09:24:46 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:46 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:46 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:46 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:46 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=30 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:47 DEBUG : : Statfs: 
2023/03/03 09:24:47 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 09:24:48 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:48 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:48 DEBUG : test/: Attr: 
2023/03/03 09:24:48 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:48 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:48 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:48 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:48 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=30 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:48 DEBUG : test/test.txt: vfs cache: starting upload
2023/03/03 09:24:48 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 09:24:48 +0000 GMT)
2023/03/03 09:24:48 INFO  : test/test.txt: Copied (replaced existing)
2023/03/03 09:24:48 DEBUG : test/test.txt: vfs cache: fingerprint now "30"
2023/03/03 09:24:48 DEBUG : test/test.txt: vfs cache: writeback object to VFS layer
2023/03/03 09:24:48 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/03 09:24:48 INFO  : test/test.txt: vfs cache: upload succeeded try #1
2023/03/03 09:24:49 DEBUG : /: Lookup: name="test"
2023/03/03 09:24:49 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 09:24:49 DEBUG : test/: Attr: 
2023/03/03 09:24:49 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 09:24:49 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 09:24:49 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 09:24:49 DEBUG : test/test.txt: Attr: 
2023/03/03 09:24:49 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-03 09:24:48 +0000 GMT)
2023/03/03 09:24:49 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=30 mode=-rw-r--r--, err=<nil>
2023/03/03 09:24:52 DEBUG : : Statfs: 
2023/03/03 09:24:52 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
^C2023/03/03 09:24:52 INFO  : Signal received: interrupt
2023/03/03 09:24:52 DEBUG : vfs cache: cleaner exiting
2023/03/03 09:24:52 ERROR : /bitrixmount/user: Unmounted rclone mount
2023/03/03 09:24:52 INFO  : Exiting...

owlthematrixblitzar · March 3, 2023, 10:37am

I have now also tried different VFS cache modes, and the only mode where the modified time is always immediately corect is in off mode, but then you cannot open and edit at the same time.

ncw · March 3, 2023, 10:58am

This is a bit of a puzzle! I have no idea where the Sat Sep 4 12:00:00 AM UTC 1999 is coming from unless that is the date set in your computer somehow.

If you look through the rclone mount can you see that date elsewhere? Maybe it is the date of the enclosing directory?

owlthematrixblitzar · March 3, 2023, 11:06am

No, the directory where the file is changed stays the same, and the mount folder is also always the same. Both have the correct time.

The strange thing is this happens on two different machines, a ubuntu server and windows pc.

My suspicion is the VFS somehow... I'll try and add some debug messages into that.

owlthematrixblitzar · March 3, 2023, 12:23pm

Ok, made some more headway in narrowing this down.

It looks like while the file is in VFS and state "Dirty" then the filesystem shows the incorrect date.

I did a cat of the metadata file of the VFS immediately after making a change

sudo cat /root/.cache/rclone/vfsMeta/buser/test/test.txt

{
	"ModTime": "2023-03-03T12:06:29.342120553Z",
	"ATime": "2023-03-03T12:06:29.343253889Z",
	"Size": 13,
	"Rs": [
		{
			"Pos": 0,
			"Size": 13
		}
	],
	"Fingerprint": "7",
	"Dirty": true

}

So in here everything looks ok except for doing a date -r on the file in the mount showing the 1999 date.
A few seconds later the file starts showing the correct date then when i do another cat of the metadata file i see this:

{
	"ModTime": "2023-03-03T12:06:29.342120553Z",
	"ATime": "2023-03-03T12:06:29.343253889Z",
	"Size": 13,
	"Rs": [
		{
			"Pos": 0,
			"Size": 13
		}
	],
	"Fingerprint": "13",
	"Dirty": false
}

So when the Dirty changes to false then the date seems to be corrected. I assume that dirty means that the file is still in cache and not yet uploaded to the server.

I also checked the modified date of the file itself in VFS cache and that also had the correct current time (and looking into file.go in the VFS folder i see comments that the modtime should be read from the dirty file itself if it exists) , so i think this is an issue with rclone and not the bitrix24 server.

owlthematrixblitzar · March 3, 2023, 12:38pm

Found the cause, but have no idea how to fix since i'm not a programmer.

The issue is in this part of code in file.go in vfs folder

	// Read the modtime from a dirty item if it exists
	if f.d.vfs.Opt.CacheMode >= vfscommon.CacheModeMinimal {
		if item := f.d.vfs.cache.DirtyItem(f._path()); item != nil {
			modTime, err := item.GetModTime()
			if err != nil {
				fs.Errorf(f._path(), "ModTime: Item GetModTime failed: %v", err)
			} else {
			fs.Debugf(nil, "Bitrix debug: modtime from dirty",f._roundModTime(modTime))
				return f._roundModTime(modTime)
			}
		}
	}

I have added a debug text showing the time of the dirty object and this function is what displays the 1999 date as seen in this log:

type or paste code here2023/03/03 12:30:06 DEBUG : rclone: Version "v1.61.1-DEV" starting with parameters ["rclone" "-vv" "mount" "buser:" "/bitrixmount/user" "--allow-other" "--uid" "1001" "--vfs-cache-mode" "full"]
2023/03/03 12:30:06 DEBUG : Creating backend with remote "buser:"
2023/03/03 12:30:06 DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
2023/03/03 12:30:06 DEBUG : found headers: 
2023/03/03 12:30:06 INFO  : webdav root '': poll-interval is not supported by this remote
2023/03/03 12:30:06 DEBUG : vfs cache: root is "/root/.cache/rclone"
2023/03/03 12:30:06 DEBUG : vfs cache: data root is "/root/.cache/rclone/vfs/buser"
2023/03/03 12:30:06 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfsMeta/buser"
2023/03/03 12:30:06 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/buser/"
2023/03/03 12:30:06 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfs/buser/" to be canonical "/root/.cache/rclone/vfs/buser"
2023/03/03 12:30:06 DEBUG : Creating backend with remote "/root/.cache/rclone/vfsMeta/buser/"
2023/03/03 12:30:06 DEBUG : fs cache: renaming cache item "/root/.cache/rclone/vfsMeta/buser/" to be canonical "/root/.cache/rclone/vfsMeta/buser"
2023/03/03 12:30:06 DEBUG : webdav root '': Mounting on "/bitrixmount/user"
2023/03/03 12:30:06 DEBUG : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/test.txt not removed, freed 0 bytes
2023/03/03 12:30:06 INFO  : vfs cache: cleaned: objects 1 (was 1) in use 0, to upload 0, uploading 0, total size 13 (was 13)
2023/03/03 12:30:06 DEBUG : : Root: 
2023/03/03 12:30:06 DEBUG : : >Root: node=/, err=<nil>
2023/03/03 12:30:20 DEBUG : /: Lookup: name="test"
2023/03/03 12:30:21 DEBUG : /: >Lookup: node=test/, err=<nil>
2023/03/03 12:30:21 DEBUG : test/: Attr: 
2023/03/03 12:30:21 DEBUG : test/: >Attr: attr=valid=1s ino=0 size=0 mode=drwxr-xr-x, err=<nil>
2023/03/03 12:30:21 DEBUG : test/: Lookup: name="test.txt"
2023/03/03 12:30:21 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 12:06:34 +0000 GMT)
2023/03/03 12:30:21 DEBUG : test/: >Lookup: node=test/test.txt, err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: Attr: 
2023/03/03 12:30:21 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-03 12:06:34 +0000 GMT)
2023/03/03 12:30:21 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=13 mode=-rw-r--r--, err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: Open: flags=OpenWriteOnly
2023/03/03 12:30:21 DEBUG : test/test.txt: Open: flags=O_WRONLY
2023/03/03 12:30:21 DEBUG : test/test.txt: newRWFileHandle: 
2023/03/03 12:30:21 DEBUG : test/test.txt: >newRWFileHandle: err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: >Open: fd=test/test.txt (rw), err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: >Open: fh=&{test/test.txt (rw)}, err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: Setattr: a=Setattr [ID=0xc Node=0x3 Uid=1000 Gid=1000 Pid=260965] size=0 handle=INVALID-0x0 lockowner
2023/03/03 12:30:21 DEBUG : test/test.txt: Truncating 1 file handles
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): openPending: 
2023/03/03 12:30:21 DEBUG : test/test.txt: vfs cache: checking remote fingerprint "13" against cached fingerprint "13"
2023/03/03 12:30:21 DEBUG : test/test.txt: vfs cache: truncate to size=13 (not needed as size correct)
2023/03/03 12:30:21 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): >openPending: err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: vfs cache: truncate to size=0
2023/03/03 12:30:21 DEBUG : test/test.txt: >Setattr: err=<nil>
2023/03/03 12:30:21 DEBUG : test/test.txt: Attr: 
2023/03/03 12:30:21 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=1999-09-04 00:00:00 +0000 UTC)
2023/03/03 12:30:21 DEBUG : test/test.txt: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): RWFileHandle.Flush
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: Write: len=20, offset=0
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): _writeAt: size=20, off=0
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): >_writeAt: n=20, err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: >Write: written=20, err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: Flush: 
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): RWFileHandle.Flush
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: >Flush: err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: Release: 
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): RWFileHandle.Release
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): close: 
2023/03/03 12:30:21 DEBUG : vfs cache: looking for range={Pos:0 Size:20} in [{Pos:0 Size:20}] - present true
2023/03/03 12:30:21 DEBUG : test/test.txt: vfs cache: setting modification time to 2023-03-03 12:30:21.595199021 +0000 UTC m=+14.882619762
2023/03/03 12:30:21 INFO  : test/test.txt: vfs cache: queuing for upload in 5s
2023/03/03 12:30:21 DEBUG : test/test.txt(0xc000812040): >close: err=<nil>
2023/03/03 12:30:21 DEBUG : &{test/test.txt (rw)}: >Release: err=<nil>
2023/03/03 12:30:22 DEBUG : : Statfs: 
2023/03/03 12:30:22 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 12:30:26 DEBUG : test/test.txt: vfs cache: starting upload
2023/03/03 12:30:27 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-03 12:30:27 +0000 GMT)
2023/03/03 12:30:27 INFO  : test/test.txt: Copied (replaced existing)
2023/03/03 12:30:27 DEBUG : test/test.txt: vfs cache: fingerprint now "20"
2023/03/03 12:30:27 DEBUG : test/test.txt: vfs cache: writeback object to VFS layer
2023/03/03 12:30:27 DEBUG : test: Added virtual directory entry vAddFile: "test.txt"
2023/03/03 12:30:27 INFO  : test/test.txt: vfs cache: upload succeeded try #1
2023/03/03 12:30:27 DEBUG : : Statfs: 
2023/03/03 12:30:27 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
2023/03/03 12:30:32 DEBUG : : Statfs: 
2023/03/03 12:30:32 DEBUG : : >Statfs: stat={Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Bsize:4096 Namelen:255 Frsize:4096}, err=<nil>
^C2023/03/03 12:30:33 INFO  : Signal received: interrupt
2023/03/03 12:30:33 DEBUG : vfs cache: cleaner exiting
2023/03/03 12:30:33 ERROR : /bitrixmount/user: Unmounted rclone mount
2023/03/03 12:30:33 INFO  : Exiting...

what is strange is that if i do a date -r on the file in the vfs cache it always shows the correct date from the moment i save

echo ssm31221222rr13123thg > /bitrixmount/user/test/test.txt
sudo date -r /root/.cache/rclone/vfs/buser/test/test.txt
Fri Mar  3 12:37:29 PM UTC 2023

ncw · March 3, 2023, 3:49pm

Excellent debugging. The problem is obvious now.

Here is the fix

v1.62.0-beta.6761.a7e9b0912.fix-vfs-modtime on branch fix-vfs-modtime (uploaded in 15-30 mins)

You'll probably need to cherry pick the commit into your branch to test it.

owlthematrixblitzar · March 3, 2023, 4:32pm

Hi Nick,

Fantastic work, this specific issue of the year 1999 seems to be fixed now, but there is still a 5s difference in modtime between dirty file and non dirty/uploaded file, which causes programs on windows to think the file was changed in the
meantime.

admin@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Fri Mar  3 04:27:40 PM UTC 2023
admin@ubuntu:~$ echo somethhing > /bitrixmount/user/test/test.txt
admin@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Fri Mar  3 04:30:59 PM UTC 2023
admin@ubuntu:~$ date -r /bitrixmount/user/test/test.txt 
Fri Mar  3 04:31:04 PM UTC 2023

This is what i get from excel

and notepad++

ncw · March 6, 2023, 10:57am

Great - thanks for testing. I've merged this to master now which means it will be in the latest beta in 15-30 minutes and released in v1.62

To fix that you need to be able to tell bitrix that when you upload a file - this is what its modification time should be.

This is not part of the WebDav standard unfortunately.

This is how Nextcloud and Owncloud do it

github.com

rclone/rclone/blob/19e8c8d42a1ae98b268527b61cd5fe700063096a/backend/webdav/webdav.go#L1320-L1322


      
          		if o.fs.useOCMtime {
          			opts.ExtraHeaders["X-OC-Mtime"] = fmt.Sprintf("%d", src.ModTime(ctx).Unix())
          		}

I would have thought rclone would hold on to the old time as for the --dir-cache-time interval

  --dir-cache-time Duration                Time to cache directory entries for (default 5m0s)

Does it? Maybe it doesn't because when the item is uploaded the object will be updated with the actual modtime set at bitrix.

owlthematrixblitzar · March 6, 2023, 12:19pm

Hi Nick,

That will be tough, since i can't easily wireshark the communication between the official buggy drive client and the server because the connection is TLS 1.3 encrypted. The useragent spoofing tip i found on a forum somewhere.

I also tried --vfs-write-back 0 , but that just made the errors from excel and others show immediately after saving.

owlthematrixblitzar · March 6, 2023, 7:00pm

Hi Nick,

Throwing in the towel, i think with your patch this is as good as this will get.

I used ghidra to decompile the binary of the official bitrix24 bdisk.exe and together with the help of wireshark found out that the abomination they created for the official client uses a combination of homebrewed "WebDAV", sqlite, dokany and their official REST API calls to upload and sync the modified times of the files (ie. upload with webdav, then using a custom REST api call change the modified time of the file).

How does windows work around this problem? I did a few minutes of googling but couldn't find a good answer.
Mounting a bitrix drive using windows webdav does work 70% of the time (windows webdav remarkably is even buggier than the bitrix24 client, which is an acomplishment) but has horrible limitations like sometimes silently discarding saved changes, not uploading changes if path is too long, max 255 characters of depth, horrific excel and word compatibility (like 165 char limit of path and filename for excel) etc.

ncw · March 7, 2023, 8:49am

Great work! Is that REST API end point documented? Rclone could call it easily enough. Even if not documented if it is not too complicated we could call it. Being able to set the modtime of uploaded files is very useful for an rclone backend as it enables modtime syncing which is much more reliable than the --size-only syncing you get without it.

I wonder if excel/etc know not to rely on timestamps on webdav somehow?

PS Are you going to send a PR for your bitrix improvements?

owlthematrixblitzar · March 7, 2023, 5:35pm

Hi Nick,

Did some more digging in the exe, it looks like no WebDav is actually used anymore, it is marked in some places as legacy and the client now uses a fully custom protocol based on REST. The main issue is that now every file and folder has a unique ID, and the filename, size, path etc. are just parameters of this ID so this looks like way too much work to reimplement, especially since from what i can google this protocol is not documented anywhere and so would have to be reverse engineered from scratch.

Just for anyone stumbling on this from google, i did try using the webdav PROPPATCH method to set the getlastmodified parameter using a unmerged patch webdav: add support for spec compliant modification time update by jpalus · Pull Request #6108 · rclone/rclone · GitHub , and i did get a 207 multipart response back from bitrix, but it looks like the request is ignored since in a PROPFIND issued after this the original getlastmodified value is presented.

I'll try and throw something together if this works decently.

I think the only option to make this work correctly, and also improve support for other backend systems that do not support setting modified time (but do have a query option like PROPFIND) would be a change to the current logic of the VFS and the metadata system, but i'm not really a programmer so i have no idea how this would be done, but i can explain my logic:

The issue to having a usable webdav mount is that when a file is opened and then saved, but the program does not close and remains open, is that in the meantime the modified date is changed when going from "Dirty" state to "uploaded state", which understandably causes the program which has the file open to notify the user that a change has occured.

To fix this a special logic would have to be added that does the following:

If a file is currently open in another program (like excel, ie. it is downloaded into the VFS cache) and then saved, then this dirty modified time is written into the metadata file of the VFS cache and shown as the modified time of the file in the mount (this works already)
Then, when the VFS write back occurs and the file is actually written to the server, instead of immediately changing the modified time of the file both in the mount and in the metadata file; a check if the file is still open in another program is made and if true then a new modified time is written into the metadata file called maybe "Servermodtime" and the old "Dirty" modified time is shown in the mount. If the file is not open in another program then the server modtime can be immediately written to the file
Then as long as the file is open in another program, periodic checks can be made on the file (every x seconds) from the server to compare the actual modified time of the file on the server (and maybe other parameters like contentlength on webdav) to the one written in the previous new "servermodtime" metadata parameter. If during these checks the modtime on the server is no longer the same as the "servermodtime" metadata parameter, then we can assume that the file on the server was changed and can be immediately downloaded to overwrite the existing file in the mount, changing the modtime which will alert the programs that somebody has changed the file and ask the user how to proceed.
Once the file is no longer open in a program then the modtime can be changed with the one in the "servermodtime" parameter that was saved when the first upload was made, and this parameter deleted from the metadata file until this file is opened again.

ncw · March 8, 2023, 12:18pm

In rclone terms these are the backends which don't support modtime - ie the ones with a - in the overview table.

Storage systems with a - in the ModTime column, means the modification read on objects is not the modification time of the file when uploaded. It is most likely the time the file was uploaded, or possibly something else (like the time the picture was taken in Google Photos).

The way we could fix this is to keep the time in the directory cache constant (controlled by the --dir-cache-time parameter).

Files will remain in the directory cache when they are being used, so this the best proxy for "open in another program" we can do.

When the file falls out of the directory cache and then is pulled back in it will have its new modification time.

I can think of two ways this could work

for these backends, don't read the updated modtime into the directory cache after writing an object. I think this is possible, but haven't checked to see how difficult this would be.
round the mod time to a multiple of the --vfs-write-back duration. So if it was set to 5s, round all mod times to the nearest 10s (say). This would be very easy and would work I think but might not be ideal.

Note that this problem has been noticed in the past with backends that do support modtime setting - we had to round the modtimes we present to FUSE to the precision that the backend supports in order to get around it.

I had a go at option 1 - let me know what you think

v1.62.0-beta.6785.1a66ed931.fix-vfs-modtime on branch fix-vfs-modtime (uploaded in 15-30 mins)

There are two commits in the branch you'll need to pull in.

owlthematrixblitzar · March 8, 2023, 3:08pm

Hi Nick,

Great work on the patch! From my quick testing it works ok in regards to editing and saving (no more nags from any kind of program that the file was modified), but it seems like --dir-cache-time no longer updates the file modified time from the server and it constantly stays the same as the dirty time, even if waiting more than 30 minutes and closing all programs, explorer etc.
I think this option may be broken/non working? I tried many permutations of options like --dir-cache-time 5s , --dir-cache-time 5 ,--dir-cache-time 0m5s and so on, but i see no action in the log every 5s with the -vv parameter

This patch gets us 90% to perfect, but there is still the issue of concurrent editing of the same file from multiple users, or changes made to the file from the server side.

Right now i can save the file on client side, and leave the program running, then on the server change the file and the client does not receive this new version. If i then save again from the program the newer version on the server is overwritten with the client version, so some kind of change polling and timestamp comparison would be needed for this kind of application.

For single user this now works great, except for the modtime is no longer updated from the server at all.

ncw · March 8, 2023, 4:14pm

Thinking about it, yes that is what will happen. It will read the modtime from the vfs cache even after the cached file is no longer present...

I could change it so it only reads the modtime from the vfs cache if the cached file is present. That would mean that the modtime would revert when the file fell out of the cache.

I would have hoped it would receive the new version after the directory cache time expires provided it is a different size.

That is how the directory cache is supposed to work anyway!

Saving files causes wrong modified time to be set for a few seconds on webdav mount with Bitrix24

What is the problem you are having with rclone?

Run the command 'rclone version' and share the full output of the command.

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

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

The rclone config contents with secrets removed.

A log from the command with the -vv flag

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

A log from the command with the `-vv` flag