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

owlthematrixblitzar · March 8, 2023, 5:15pm

Hi Nick,

I changed the file on the server, and with --dump bodies i could see that rclone did do a PROPFIND and the size and modified time were changed but it was not updated in cache. - SEE POST 2

--- Ignore this part, just re-read your post and see that you already know of this issue. Leaving this old edit since it contains logs---

And now after a few hours of inactivity i restarted rclone again to give logs of exactly what happens and i see there is a new issue. Now the cache of the file was actually deleted from the VFS and then when a propfind was done the current time was used as a dirty mod time, even though the file was never downloaded again (all i did was read the attribute using get-children with powershell, i did not open or download the file).

Here is a log with --dump-bodies

C:\Users\user\Documents\rclone-1.61.1>rclone -vv mount bitrixuser: H: --vfs-cache-mode full --dir-cache-time 0m5s --dump-bodies
2023/03/08 17:32:41 NOTICE: --dump-bodies is obsolete - please use --dump bodies instead
2023/03/08 17:32:41 DEBUG : rclone: Version "v1.61.1-DEV" starting with parameters ["rclone" "-vv" "mount" "bitrixuser:" "H:" "--vfs-cache-mode" "full" "--dir-cache-time" "0m5s" "--dump-bodies"]
2023/03/08 17:32:41 DEBUG : Creating backend with remote "bitrixuser:"
2023/03/08 17:32:41 DEBUG : Using config file from "C:\\Users\\user\\AppData\\Roaming\\rclone\\rclone.conf"
2023/03/08 17:32:41 DEBUG : found headers:
2023/03/08 17:32:41 DEBUG : You have specified to dump information. Please be noted that the Accept-Encoding as shown may not be correct in the request and the response may not show Content-Encoding if the go standard libraries auto gzip encoding was in effect. In this case the body of the request will be gunzipped before showing it.
2023/03/08 17:32:41 INFO  : webdav root '': poll-interval is not supported by this remote
2023/03/08 17:32:41 DEBUG : vfs cache: root is "C:\\Users\\user\\AppData\\Local\\rclone"
2023/03/08 17:32:41 DEBUG : vfs cache: data root is "\\\\?\\C:\\Users\\user\\AppData\\Local\\rclone\\vfs\\bitrixuser"
2023/03/08 17:32:41 DEBUG : vfs cache: metadata root is "\\\\?\\C:\\Users\\user\\AppData\\Local\\rclone\\vfsMeta\\bitrixuser"
2023/03/08 17:32:42 DEBUG : Creating backend with remote "C:/Users/user/AppData/Local/rclone/vfs/bitrixuser/"
2023/03/08 17:32:42 DEBUG : fs cache: renaming cache item "C:/Users/user/AppData/Local/rclone/vfs/bitrixuser/" to be canonical "//?/C:/Users/user/AppData/Local/rclone/vfs/bitrixuser"
2023/03/08 17:32:42 DEBUG : Creating backend with remote "C:/Users/user/AppData/Local/rclone/vfsMeta/bitrixuser/"
2023/03/08 17:32:42 DEBUG : fs cache: renaming cache item "C:/Users/user/AppData/Local/rclone/vfsMeta/bitrixuser/" to be canonical "//?/C:/Users/user/AppData/Local/rclone/vfsMeta/bitrixuser"
2023/03/08 17:32:42 DEBUG : Network mode mounting is disabled
2023/03/08 17:32:42 DEBUG : Mounting on "H:" ("bitrixuser")
2023/03/08 17:32:42 INFO  : test/Book1.xlsx: vfs cache: removed cache file as Removing old cache file not in use
2023/03/08 17:32:42 DEBUG : test/Book1.xlsx: vfs cache: removed metadata from cache as Removing old cache file not in use
2023/03/08 17:32:42 DEBUG : webdav root '': Mounting with options: ["-o" "attr_timeout=1" "-o" "uid=-1" "-o" "gid=-1" "--FileSystemName=rclone" "-o" "volname=bitrixuser"]
2023/03/08 17:32:42 INFO  : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/Book1.xlsx was removed, freed 8689 bytes
2023/03/08 17:32:42 DEBUG : webdav root '': Init:
2023/03/08 17:32:42 INFO  : test/test.txt: vfs cache: removed cache file as Removing old cache file not in use
2023/03/08 17:32:42 DEBUG : webdav root '': >Init:
2023/03/08 17:32:42 DEBUG : test/test.txt: vfs cache: removed metadata from cache as Removing old cache file not in use
2023/03/08 17:32:42 INFO  : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/test.txt was removed, freed 77 bytes
2023/03/08 17:32:42 INFO  : test/~$Book1.xlsx: vfs cache: removed cache file as Removing old cache file not in use
2023/03/08 17:32:42 DEBUG : /: Statfs:
2023/03/08 17:32:42 DEBUG : test/~$Book1.xlsx: vfs cache: removed metadata from cache as Removing old cache file not in use
2023/03/08 17:32:42 INFO  : vfs cache RemoveNotInUse (maxAge=3600000000000, emptyOnly=false): item test/~$Book1.xlsx was removed, freed 0 bytes
2023/03/08 17:32:42 INFO  : vfs cache: cleaned: objects 0 (was 3) in use 0, to upload 0, uploading 0, total size 0 (was 8.561Ki)
2023/03/08 17:32:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:42 DEBUG : HTTP REQUEST (req 0xc000826b00)
2023/03/08 17:32:42 DEBUG : PROPFIND /company/personal/user/10/disk/path/ HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Content-Length: 139
Authorization: XXXX
Depth: 0
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

<?xml version="1.0" ?>
<D:propfind xmlns:D="DAV:">
 <D:prop>
  <D:quota-available-bytes/>
  <D:quota-used-bytes/>
 </D:prop>
</D:propfind>
2023/03/08 17:32:42 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:42 DEBUG : HTTP RESPONSE (req 0xc000826b00)
2023/03/08 17:32:42 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 1090
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/xml; charset="utf-8"
Date: Wed, 08 Mar 2023 16:32:42 GMT
Dav: 1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=hCztfmUamEFANq7zENVaJZe8NOqJf4n1; expires=Sun, 12-Mar-2023 16:32:42 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 207 Multi-Status

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:" xmlns:Office="urn:schemas-microsoft-com:office:office" xmlns:Repl="http://schemas.microsoft.com/repl/" xmlns:Z="urn:schemas-microsoft-com:">
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/</D:href>
   <D:propstat>
    <D:prop>
     <D:name>bitrixuser</D:name>
     <D:creationdate ns0:dt="dateTime.tz">2021-09-06T06:15:08Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 01 Mar 2023 11:33:12 GMT</D:getlastmodified>
     <D:iscollection>1</D:iscollection>
     <D:resourcetype><collection/></D:resourcetype>
     <D:getcontenttype>httpd/unix-directory</D:getcontenttype>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
</D:multistatus>
2023/03/08 17:32:42 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:42 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Readlink:
2023/03/08 17:32:42 DEBUG : /: >Readlink: linkPath="", errc=-40
2023/03/08 17:32:42 DEBUG : /: Getxattr: name="non-existant-a11ec902d22f4ec49003af15282d3b00"
2023/03/08 17:32:42 DEBUG : /: >Getxattr: errc=-40, value=""
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
The service rclone has been started.
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: Opendir:
2023/03/08 17:32:42 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:42 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Statfs:
2023/03/08 17:32:42 DEBUG : /: >Statfs: stat={Bsize:4096 Frsize:4096 Blocks:274877906944 Bfree:274877906944 Bavail:274877906944 Files:1000000000 Ffree:1000000000 Favail:0 Fsid:0 Flag:0 Namemax:255}, errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: Opendir:
2023/03/08 17:32:42 DEBUG : /: Releasedir: fh=0x0
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:42 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:42 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Opendir:
2023/03/08 17:32:42 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:42 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:42 DEBUG : /: Releasedir: fh=0x0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Opendir: errc=0, fh=0x1
2023/03/08 17:32:42 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Releasedir: fh=0x1
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:42 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:42 DEBUG : /: Opendir:
2023/03/08 17:32:42 DEBUG : /: Opendir:
2023/03/08 17:32:42 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:42 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:42 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/03/08 17:32:42 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:42 DEBUG : /: Releasedir: fh=0x0
2023/03/08 17:32:42 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:42 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:42 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/03/08 17:32:42 DEBUG : /: Releasedir: fh=0x0
2023/03/08 17:32:42 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:45 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:45 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:45 DEBUG : HTTP REQUEST (req 0xc0008b2200)
2023/03/08 17:32:46 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2023/03/08 17:32:46 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2023/03/08 17:32:46 DEBUG : /autorun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:46 DEBUG : /autorun.inf: >Getattr: errc=-2
2023/03/08 17:32:46 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:46 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:46 DEBUG : /: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:46 DEBUG : /: >Getattr: errc=0
2023/03/08 17:32:46 DEBUG : /: Opendir:
2023/03/08 17:32:46 DEBUG : /: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:46 DEBUG : /: >OpenFile: fd=/ (r), err=<nil>
2023/03/08 17:32:46 DEBUG : /: >Opendir: errc=0, fh=0x0
2023/03/08 17:32:46 DEBUG : /: Releasedir: fh=0x0
2023/03/08 17:32:46 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:32:46 DEBUG : /AutoRun.inf: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:46 DEBUG : /AutoRun.inf: >Getattr: errc=-2
2023/03/08 17:32:58 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:58 DEBUG : : Re-reading directory (13.0685853s old)
2023/03/08 17:32:58 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:58 DEBUG : HTTP REQUEST (req 0xc000726400)
2023/03/08 17:32:59 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:59 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:59 DEBUG : HTTP REQUEST (req 0xc0008b2200)
2023/03/08 17:32:59 DEBUG : PROPFIND /company/personal/user/10/disk/path/test/ HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Authorization: XXXX
Depth: 1
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

2023/03/08 17:32:59 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:32:59 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:59 DEBUG : HTTP RESPONSE (req 0xc0008b2200)
2023/03/08 17:32:59 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 3770
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/xml; charset="utf-8"
Date: Wed, 08 Mar 2023 16:32:59 GMT
Dav: 1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=AtttECFsw9QPh5ETzDb3R4aeVlBZ2B0M; expires=Sun, 12-Mar-2023 16:32:59 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 207 Multi-Status

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:" xmlns:Office="urn:schemas-microsoft-com:office:office" xmlns:Repl="http://schemas.microsoft.com/repl/" xmlns:Z="urn:schemas-microsoft-com:">
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/</D:href>
   <D:propstat>
    <D:prop>
     <D:name>test</D:name>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-01T11:33:12Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:46:18 GMT</D:getlastmodified>
     <D:iscollection>1</D:iscollection>
     <D:resourcetype><collection/></D:resourcetype>
     <D:getcontenttype>httpd/unix-directory</D:getcontenttype>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/test.txt</D:href>
   <D:propstat>
    <D:prop>
     <D:name>test.txt</D:name>
     <D:getcontentlength>77</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-01T11:33:48Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:31:45 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/~%24Book1.xlsx</D:href>
   <D:propstat>
    <D:prop>
     <D:name>~$Book1.xlsx</D:name>
     <D:getcontentlength>165</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-08T14:38:55Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:38:55 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/Book1.xlsx</D:href>
   <D:propstat>
    <D:prop>
     <D:name>Book1.xlsx</D:name>
     <D:getcontentlength>7667</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-08T14:44:41Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:46:18 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
</D:multistatus>
2023/03/08 17:32:59 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 14:31:45 +0000 GMT)
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 14:38:55 +0000 GMT)
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 14:46:18 +0000 GMT)
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-08 14:46:18 +0000 GMT)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from http header%!(EXTRA time.Time=2023-03-08 14:46:18 +0000 GMT)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Flush: fh=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc0008b6480): RWFileHandle.Flush
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Release: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc0008b6480): RWFileHandle.Release
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc0008b6480): close:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc0008b6480): >close: err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Flush: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a0c0): RWFileHandle.Flush
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Release: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a0c0): RWFileHandle.Release
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a0c0): close:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a0c0): >close: err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Flush: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a100): RWFileHandle.Flush
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Release: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a100): RWFileHandle.Release
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a100): close:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc00082a100): >close: err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:32:59 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:32:59.1696072 +0100 CET m=+17.383191501)
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Flush: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc000794980): RWFileHandle.Flush
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: Release: fh=0x0
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc000794980): RWFileHandle.Release
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc000794980): close:
2023/03/08 17:32:59 DEBUG : test/Book1.xlsx(0xc000794980): >close: err=<nil>
2023/03/08 17:32:59 DEBUG : /test/Book1.xlsx: >Release: errc=0
The service rclone has been stopped.
2023/03/08 17:33:16 DEBUG : webdav root '': Destroy:
2023/03/08 17:33:16 DEBUG : webdav root '': >Destroy:
2023/03/08 17:33:16 DEBUG : Not calling host.Unmount as mount already Destroyed
2023/03/08 17:33:16 DEBUG : vfs cache: cleaner exiting
2023/03/08 17:33:16 DEBUG : Unmounted successfully
2023/03/08 17:33:16 ERROR : H:: Unmounted rclone mount
2023/03/08 17:33:16 DEBUG : rclone: Version "v1.61.1-DEV" finishing with parameters ["rclone" "-vv" "mount" "bitrixuser:" "H:" "--vfs-cache-mode" "full" "--dir-cache-time" "0m5s" "--dump-bodies"]

C:\Users\user\Documents\rclone-1.61.1>

continued in post 2

owlthematrixblitzar · March 8, 2023, 5:15pm

Once i download/open the file the correct modified time is then shown.

Here is a log where i upload a change of an excel file, then i make a change on the server then try to read the modified time of the file which forces a PROPFIND and you can see that both the content length and modtime on the server are different from the uploaded file, but the local file from the cache remains

---useless junk since command start---

2023/03/08 17:53:36 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x2
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: Flush: fh=0x2
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx(0xc000996240): RWFileHandle.Flush
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: Release: fh=0x2
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx(0xc000996240): RWFileHandle.Release
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx(0xc000996240): close:
2023/03/08 17:53:36 DEBUG : test/Book1.xlsx(0xc000996240): >close: err=<nil>
2023/03/08 17:53:36 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:53:37 DEBUG : test/Book1.xlsx: vfs cache: starting upload
2023/03/08 17:53:37 DEBUG : Bitrix debug: modtime for temp new object%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:53:37 DEBUG : Bitrix debug: modtime ctx put object%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : HTTP REQUEST (req 0xc0009a6000)
2023/03/08 17:53:37 DEBUG : MKCOL /company/personal/user/10/disk/path/test/ HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Authorization: XXXX
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : HTTP RESPONSE (req 0xc0009a6000)
2023/03/08 17:53:37 DEBUG : HTTP/2.0 409 Conflict
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/html; charset=UTF-8
Date: Wed, 08 Mar 2023 16:53:37 GMT
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=dRKgIclWHX4Yu602NQS63SxQSUMM34AJ; expires=Sun, 12-Mar-2023 16:53:37 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 409 Conflict
Content-Length: 0

2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : HTTP REQUEST (req 0xc000b62700)
2023/03/08 17:53:37 DEBUG : PROPFIND /company/personal/user/10/disk/path/test/ HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Authorization: XXXX
Depth: 0
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : HTTP RESPONSE (req 0xc000b62700)
2023/03/08 17:53:37 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 1083
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/xml; charset="utf-8"
Date: Wed, 08 Mar 2023 16:53:37 GMT
Dav: 1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=utnMN53CYQ2ry6un4DDqRF1N5PMWzwHm; expires=Sun, 12-Mar-2023 16:53:37 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 207 Multi-Status

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:" xmlns:Office="urn:schemas-microsoft-com:office:office" xmlns:Repl="http://schemas.microsoft.com/repl/" xmlns:Z="urn:schemas-microsoft-com:">
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/</D:href>
   <D:propstat>
    <D:prop>
     <D:name>test</D:name>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-01T11:33:12Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 16:53:32 GMT</D:getlastmodified>
     <D:iscollection>1</D:iscollection>
     <D:resourcetype><collection/></D:resourcetype>
     <D:getcontenttype>httpd/unix-directory</D:getcontenttype>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
</D:multistatus>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : HTTP REQUEST (req 0xc0007faa00)


//////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////
SIZE OF UPLOADED DATA

2023/03/08 17:53:37 DEBUG : PUT /company/personal/user/10/disk/path/test/Book1.xlsx HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Content-Length: 10435







Authorization: XXXX
Content-Type: application/vnd.openxmlformats-officedocument.spreadsheetml.sheet
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

--- GARBAGE XLS DATA---

2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : HTTP RESPONSE (req 0xc0007faa00)
2023/03/08 17:53:37 DEBUG : HTTP/2.0 201 Created
Content-Length: 0
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/html; charset=UTF-8
Date: Wed, 08 Mar 2023 16:53:38 GMT
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Location: https://example.com:443/company/personal/user/10/disk/path/test/Book1.xlsx
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=8r1MKKKiAljy0opzsuV5Jbg54v93NYC7; expires=Sun, 12-Mar-2023 16:53:37 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Content-Type-Options: nosniff
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 201 Created

2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : HTTP REQUEST (req 0xc000691200)
2023/03/08 17:53:37 DEBUG : PROPFIND /company/personal/user/10/disk/path/test/Book1.xlsx HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Authorization: XXXX
Depth: 1
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

2023/03/08 17:53:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : HTTP RESPONSE (req 0xc000691200)
2023/03/08 17:53:37 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 1124
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/xml; charset="utf-8"
Date: Wed, 08 Mar 2023 16:53:38 GMT
Dav: 1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=RHETdxwibSuCEEnnDDj37EQYCyL8EuwI; expires=Sun, 12-Mar-2023 16:53:38 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 207 Multi-Status

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:" xmlns:Office="urn:schemas-microsoft-com:office:office" xmlns:Repl="http://schemas.microsoft.com/repl/" xmlns:Z="urn:schemas-microsoft-com:">
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/Book1.xlsx</D:href>
   <D:propstat>
    <D:prop>
     <D:name>Book1.xlsx</D:name>
     <D:getcontentlength>10435</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-08T16:53:37Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 16:53:37 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
</D:multistatus>
2023/03/08 17:53:37 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:53:37 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 16:53:37 +0000 GMT)
2023/03/08 17:53:37 INFO  : test/Book1.xlsx: Copied (new)
2023/03/08 17:53:37 DEBUG : test/Book1.xlsx: vfs cache: fingerprint now "10435"
2023/03/08 17:53:37 DEBUG : test/Book1.xlsx: vfs cache: writeback object to VFS layer
2023/03/08 17:53:37 DEBUG : test: Added virtual directory entry vAddFile: "Book1.xlsx"
2023/03/08 17:53:37 INFO  : test/Book1.xlsx: vfs cache: upload succeeded try #1
2023/03/08 17:53:45 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:53:45 DEBUG : : Re-reading directory (9.502147s old)
2023/03/08 17:53:45 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:53:45 DEBUG : HTTP REQUEST (req 0xc0007fa200)
2023/03/08 17:53:45 DEBUG : PROPFIND /company/personal/user/10/disk/path/ HTTP/1.1

--useless data --

2023/03/08 17:55:36 DEBUG : /test: >Getattr: errc=0
2023/03/08 17:55:36 DEBUG : /: Releasedir: fh=0x2
2023/03/08 17:55:36 DEBUG : /: >Releasedir: errc=0
2023/03/08 17:55:37 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:37 DEBUG : test: Re-reading directory (1m52.0005695s old)
2023/03/08 17:55:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:55:37 DEBUG : HTTP REQUEST (req 0xc00015ea00)
2023/03/08 17:55:37 DEBUG : PROPFIND /company/personal/user/10/disk/path/test/ HTTP/1.1
Host: example.com
User-Agent: Microsoft-WebDAV-MiniRedir/6.1.7601
Authorization: XXXX
Depth: 1
Referer: https://example.com/company/personal/user/10/disk/path/
Accept-Encoding: gzip

2023/03/08 17:55:37 DEBUG : >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
2023/03/08 17:55:38 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:55:38 DEBUG : HTTP RESPONSE (req 0xc00015ea00)
2023/03/08 17:55:38 DEBUG : HTTP/2.0 207 Multi-Status
Content-Length: 3770
Cache-Control: no-store, no-cache, must-revalidate
Content-Type: text/xml; charset="utf-8"
Date: Wed, 08 Mar 2023 16:55:38 GMT
Dav: 1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
P3p: policyref="/bitrix/p3p.xml", CP="NON DSP COR CUR ADM DEV PSA PSD OUR UNR BUS UNI COM NAV INT DEM STA"
Pragma: no-cache
Server: nginx
Set-Cookie: PHPSESSID=6ArGdeQzvQmBD3P4tIj2Icu5q7ugQMeG; expires=Sun, 12-Mar-2023 16:55:38 GMT; Max-Age=345600; path=/; HttpOnly
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Set-Cookie: BITRIX_SM_PK=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/
Vary: HTTPS
X-Dav-Powered-By: Bitrix Site Manager
X-Frame-Options: SAMEORIGIN
X-Powered-Cms: Bitrix Site Manager (2614bb9269e468595556b7c361949366)
X-Webdav-Status: 207 Multi-Status

<?xml version="1.0" encoding="utf-8"?>
<D:multistatus xmlns:D="DAV:" xmlns:Office="urn:schemas-microsoft-com:office:office" xmlns:Repl="http://schemas.microsoft.com/repl/" xmlns:Z="urn:schemas-microsoft-com:">
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/</D:href>
   <D:propstat>
    <D:prop>
     <D:name>test</D:name>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-01T11:33:12Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 16:55:22 GMT</D:getlastmodified>
     <D:iscollection>1</D:iscollection>
     <D:resourcetype><collection/></D:resourcetype>
     <D:getcontenttype>httpd/unix-directory</D:getcontenttype>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/test.txt</D:href>
   <D:propstat>
    <D:prop>
     <D:name>test.txt</D:name>
     <D:getcontentlength>77</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-01T11:33:48Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:31:45 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/~%24Book1.xlsx</D:href>
   <D:propstat>
    <D:prop>
     <D:name>~$Book1.xlsx</D:name>
     <D:getcontentlength>165</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-08T14:38:55Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 14:38:55 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
 <D:response xmlns:ns0="urn:uuid:c2f41010-65b3-11d1-a29f-00aa00c14882/">
  <D:href>/company/personal/user/10/disk/path/test/Book1.xlsx</D:href>
   <D:propstat>
    <D:prop>
    
    
   
//////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////
   HERE YOU CAN SEE SIZE ON SERVER IS DIFFERENT THAN IN CACHE
   
    
    
     <D:name>Book1.xlsx</D:name>
     <D:getcontentlength>7684</D:getcontentlength>
     <D:creationdate ns0:dt="dateTime.tz">2023-03-08T16:53:37Z</D:creationdate>
     <D:getlastmodified ns0:dt="dateTime.rfc1123">Wed, 08 Mar 2023 16:55:22 GMT</D:getlastmodified>
     <D:iscollection>0</D:iscollection>
     <D:getcontenttype/>
     <D:isreadonly/>
     <D:ishidden/>
     <D:resourcetype/>
     <D:supportedlock><D:lockentry><D:lockscope><D:exclusive/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry><D:lockentry><D:lockscope><D:shared/></D:lockscope><D:locktype><D:write/></D:locktype></D:lockentry></D:supportedlock>
    </D:prop>
    <D:status>HTTP/1.1 200 OK</D:status>
   </D:propstat>
 </D:response>
</D:multistatus>
2023/03/08 17:55:38 DEBUG : <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 14:31:45 +0000 GMT)
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 14:38:55 +0000 GMT)
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from metadata info%!(EXTRA time.Time=2023-03-08 16:55:22 +0000 GMT)
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x2
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0x2
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Flush: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007bc500): RWFileHandle.Flush
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Release: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007bc500): RWFileHandle.Release
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007bc500): close:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007bc500): >close: err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x2
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Flush: fh=0x2
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce040): RWFileHandle.Flush
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Release: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce040): RWFileHandle.Release
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce040): close:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce040): >close: err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x2
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Flush: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc000c4c000): RWFileHandle.Flush
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Release: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc000c4c000): RWFileHandle.Release
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc000c4c000): close:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc000c4c000): >close: err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Release: errc=0
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Getattr: fh=0xFFFFFFFFFFFFFFFF
2023/03/08 17:55:38 DEBUG : Bitrix debug: modtime from dirty%!(EXTRA time.Time=2023-03-08 17:53:31.1434255 +0100 CET)
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Getattr: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenEx: flags=0x0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: OpenFile: flags=O_RDONLY, perm=-rwxrwxrwx
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: Open: flags=O_RDONLY
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: newRWFileHandle:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >newRWFileHandle: err=<nil>
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx: >Open: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenFile: fd=test/Book1.xlsx (rw), err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >OpenEx: errc=0, fh=0x2
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Flush: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce080): RWFileHandle.Flush
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Flush: errc=0
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: Release: fh=0x2
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce080): RWFileHandle.Release
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce080): close:
2023/03/08 17:55:38 DEBUG : test/Book1.xlsx(0xc0007ce080): >close: err=<nil>
2023/03/08 17:55:38 DEBUG : /test/Book1.xlsx: >Release: errc=0
The service rclone has been stopped.
2023/03/08 17:55:56 DEBUG : webdav root '': Destroy:
2023/03/08 17:55:56 DEBUG : webdav root '': >Destroy:
2023/03/08 17:55:56 DEBUG : vfs cache: cleaner exiting
2023/03/08 17:55:56 DEBUG : Not calling host.Unmount as mount already Destroyed
2023/03/08 17:55:56 DEBUG : Unmounted successfully
2023/03/08 17:55:56 ERROR : H:: Unmounted rclone mount
2023/03/08 17:55:56 DEBUG : rclone: Version "v1.61.1-DEV" finishing with parameters ["rclone" "-vv" "mount" "bitrixuser:" "H:" "--vfs-cache-mode" "full" "--dir-cache-time" "0m5s" "--dump-bodies"]

C:\Users\user\Documents\rclone-1.61.1>

ncw · March 9, 2023, 11:47am

Good

When you say the local cache file remains that is probably OK unless it gave you that data when you read the file.

This messes up the idea of reading the modtime from the cache file though...

OK here is a new approach - this introduces a concept of a virtual modtime for a file. If the OS reads the modtime of the file on a backend which doesn't support modtimes then it will cache the last modtime read until the directory cache expires.

This seems to work in my testing - let me know how it works for you

v1.62.0-beta.6788.b4e2dca86.fix-vfs-modtime-2 on branch fix-vfs-modtime-2 (uploaded in 15-30 mins)

owlthematrixblitzar · March 9, 2023, 1:27pm

Hi Nick,

Thanks for the patch, this now fixes the download of fresh files from the server but the modtime of the file in the mount still stays the same dirty one untill the moment when you try and open the file

What is the logic for expiring the directory cache? I tried with your patch and --dir-cache-time 0m20s and the file even after closing all programs and waiting 5 minutes the file still had the same dirty modtime even though on the server there was a file with a newer modtime which i can see was read in periodic propfinds from rclone.

ncw · March 9, 2023, 3:51pm

That sounds like what I would expect.

The file will have to leave the directory cache to get a new modtime. Or more precisely the updated object needs to be read into the directory cache before it is updated.

The directory cache expires roughly after the --dir-cache-time but it isn't exact as it will only do expiries when the directory is read. It seemed to be taking about 60s when I had --dir-cache-time 30s for reasons I didn't investigate!

owlthematrixblitzar · March 9, 2023, 4:26pm

Hi Nick,

Ok, will keep testing this for the next few days to see if there are any other issues. Right now this works great for single users where the files on the server are not changed except by rclone.
In case when a file is opened, then it is changed on the server and then saved on the rclone client the rclone version of the file will overwrite the one on the server (in case of bitrix24 this clobbering also changes the internal ID of the file, and the old version is given a random.tmp filename and sent to the trash, so bitrix correctly identifies a conflict and instead of versioning the file like usual it makes a new ID), but other than this edge case it seems to be working great, thanks again for the great work!

ncw · March 9, 2023, 4:57pm

This will always be the case if the change happens within the --dir-cache-time window. That is what it is there for to give a limit to that behaviour.

Great!

If you could let me know how it is in 24h that would be good and I'll consider whether to merge it for v1.62 which is coming very soon.

owlthematrixblitzar · March 9, 2023, 5:22pm

Ok, will do tommorow

owlthematrixblitzar · March 10, 2023, 2:09pm

Hi Nick,

Happy to report no issues that i can see with the v2 version of the patch.

ncw · March 10, 2023, 3:01pm

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

I think that is a very useful fix for non modtime supporting backends. Hopefully it doesn't cause any problems!

system · April 9, 2023, 3:01pm

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