Rclone mount and changing timestamps after writes

Help and Support
1

Hello,

I searched the documentation and forum for some time but did not find any information yet and hope that via this forum I can get some insights.

I use rclone mount with Object Storage over the s3 integration.

I also enabled "--vfs-cache-mode writes" with defaults which I think is 5 seconds.

Now I observed the following

If I update a file like this at time 09:07:27 : echo "test" >> /.../test.txt

and immediately call -lna --full-time I see
.... .. 2021-03-04 09:02:54.848276626 +0000 test.txt

This is the timestamp of my last change, not current time when I did the echo above (That is 09:07:27). The file is however immediately updated. I can see the update when I immediately open it (before write cache syncs)

I do then call constantly -lna --full-time and after roughly 5 seconds (I think when write cache writes back to OS), I see that the timestamp jumps without any further action from my side

.....2021-03-04 09:07:32.531555134 +0000 test.txt

This is the time of echo + roughly 5 seconds.

The time is exactly identical to the timestamp the file has in object storage.

Can someone explain if this is in deed expected (and maybe can shortly tell why)?

Are there config options that could change the behavior so that the timestamp is updated on save with the time it is when the save actually happens and that time stays also when write to OS kicks in?

Why this matters? The legacy app I use (and cannot modify) has some built in logic that remembers the time the file was written (current) and when I then modify the file and try to store again, before actually storing , it compares the remembered time with the time on disk (that is current + roughly 5 seconds) and then it gives a warning that the file changed in the background.

2

What version of rclone are you using?

I think this behaviour was fixed in a recent version or maybe in the latest beta.

3

Hello Nick. Thanks for responding. I used 1.54.0 for linux installed via: https://rclone.org/install.sh

I will check the beta.

4

If that doesn't fix it, could you post your config with secrets removed and your mount command line please?

Also a log with -vv of just that event would be very useful - thanks.

5

Hello. I tried again with the beta and correlated outputs of my script (with time) with the logs from rclone

Summary: I still see that the time switches some time after the write

My mount command
!rclone mount :s3:rclonejs /rclone222 -vv --s3-acl=private --s3-env-auth=false --s3-access-key-id=... --s3-secret-access-key=... --s3-endpoint=s3.us-south.cloud-object-storage.appdomain.cloud --s3-location-constraint=us-south-standard --debug-fuse -v --vfs-cache-mode writes

Here is the init block
2021/03/11 16:49:36 DEBUG : rclone: Version "v1.55.0-beta.5249.59ed70ca9"
2021/03/11 16:49:36 DEBUG : Creating backend with remote ":s3:rclonejs"
2021/03/11 16:49:36 NOTICE: Config file "/root/.config/rclone/rclone.conf" not found - using defaults
2021/03/11 16:49:36 INFO : S3 bucket rclonejs: poll-interval is not supported by this remote
2021/03/11 16:49:36 DEBUG : vfs cache: root is "/root/.cache/rclone/vfs/:s3/rclonejs"
2021/03/11 16:49:36 DEBUG : vfs cache: metadata root is "/root/.cache/rclone/vfs/:s3/rclonejs"
2021/03/11 16:49:36 DEBUG : Creating backend with remote "/root/.cache/rclone/vfs/:s3/rclonejs"
2021/03/11 16:49:36 DEBUG : S3 bucket rclonejs: Mounting on "/rclone222"
2021/03/11 16:49:36 INFO : vfs cache: cleaned: objects 0 (was 0) in use 0, to upload 0, uploading 0, total size 0 (was 0)

Write happens: Thu Mar 11 17:05:07 UTC 2021

At that time I see that vfs cache gets active

2021/03/11 17:05:07 DEBUG : vfs cache: looking for range={Pos:0 Size:30} in [{Pos:0 Size:30}] - present true
2021/03/11 17:05:07 DEBUG : test_March_10/test.txt: vfs cache: setting modification time to 2021-03-11 17:05:07.114220898 +0000 UTC m=+930.333001916
2021/03/11 17:05:07 INFO : test_March_10/test.txt: vfs cache: queuing for upload in 5s

....

and remembers the timestamp

Still for the next couple of seconds , ls gives the "old" timestamp of the file

Thu Mar 11 17:05:07 UTC 2021
total 1
drwxr-xr-x 1 0 0 0 2021-03-11 16:50:04.869983803 +0000 .
drwxr-xr-x 1 0 0 0 2021-03-11 16:49:36.841348206 +0000 ..
-rw-r--r-- 1 0 0 30 2021-03-11 16:58:17.206742784 +0000 test.txt
Thu Mar 11 17:05:09 UTC 2021
total 1
drwxr-xr-x 1 0 0 0 2021-03-11 16:50:04.869983803 +0000 .
drwxr-xr-x 1 0 0 0 2021-03-11 16:49:36.841348206 +0000 ..
-rw-r--r-- 1 0 0 30 2021-03-11 16:58:17.206742784 +0000 test.txt
Thu Mar 11 17:05:10 UTC 2021
total 1
drwxr-xr-x 1 0 0 0 2021-03-11 16:50:04.869983803 +0000 .
drwxr-xr-x 1 0 0 0 2021-03-11 16:49:36.841348206 +0000 ..
-rw-r--r-- 1 0 0 30 2021-03-11 16:58:17.206742784 +0000 test.txt
Thu Mar 11 17:05:11 UTC 2021
total 1
drwxr-xr-x 1 0 0 0 2021-03-11 16:50:04.869983803 +0000 .
drwxr-xr-x 1 0 0 0 2021-03-11 16:49:36.841348206 +0000 ..
-rw-r--r-- 1 0 0 30 2021-03-11 16:58:17.206742784 +0000 test.txt

Then vfs does something again

2021/03/11 17:05:12 DEBUG : test_March_10/test.txt: vfs cache: starting upload

2021/03/11 17:05:12 DEBUG : test_March_10/test.txt: MD5 = 69be8471fd63704e026d6978c24ad0ad OK
2021/03/11 17:05:12 INFO : test_March_10/test.txt: Copied (replaced existing)

And here it seems the fingerprint changes and something is written back to the cache

2021/03/11 17:05:12 DEBUG : test_March_10/test.txt: vfs cache: fingerprint now "30,2021-03-11 17:05:07.114220898 +0000 UTC,69be8471fd63704e026d6978c24ad0ad"
2021/03/11 17:05:12 DEBUG : test_March_10/test.txt: vfs cache: writeback object to VFS layer

2021/03/11 17:05:12 DEBUG : test_March_10: Added virtual directory entry vAddFile: "test.txt"

2021/03/11 17:05:12 INFO : test_March_10/test.txt: vfs cache: upload succeeded try #1

Now the time switched also on the ls calls

Thu Mar 11 17:05:12 UTC 2021
total 1
drwxr-xr-x 1 0 0 0 2021-03-11 16:50:04.869983803 +0000 .
drwxr-xr-x 1 0 0 0 2021-03-11 16:49:36.841348206 +0000 ..
-rw-r--r-- 1 0 0 30 2021-03-11 17:05:07.114220898 +0000 test.txt

6

Thank you for those logs - I can see exactly what is going on.

What is happening is that the modification time is being read from the object which doesn't change until it is uploaded.

We actually had the same problem with the size, so I've fixed the modtime in the same way we fixed the size. Normally rclone will read the modtime from the object unless the backing file is dirty (ie not uploaded), in which it will read it direct from the backing file.

Can you give this a go?

v1.55.0-beta.5263.d85940454.fix-vfs-modtime on branch fix-vfs-modtime (uploaded in 15-30 mins)

7

Slightly off-topic, there are 2 branches with different vfs mod-time related fixes. Would it be possible to get them merged into this or the branch deleted (if we don't want them)?

1 Like
8

Yes well spotted! I didn't find the other branch until I'd fixed it again.

I think the new code is better so I will delete the old branch.

1 Like
9

Sorry for another off-topic question, but do you think you can handle the following issue too as part of this set of fixes or does that require a bigger change?

10

Will reply on the issue

11

I installed the special build and it worked fine for me. Thank you very much.

One question. Is there any info (link) on the release schedule of rclone?

Is there a fixed schedule of releases every month /quarter..?

Or in other words. By when would this fix be part of the regular release?

12

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

You can look at the date of the milestone in the github project

So end of the month :slight_smile:

13

@ncw When doing a test of a pending PR, I found that running tar with a vfs mount using 1.55.0 release (or the current master) would cause the following warning message for each file.
tar: /mnt/fs1/clone/current/.git/objects/42/ec02f3c548d806211565adc2d27cba3537dced: file changed as we read it

I tried 1.54.1 with the same test scenario and did not get this error. It looks that the modification time fix here might have created this problem?

ModTime (in file.go) calls cache.DirtyItem -> item.IsDirty, which in turn references item.metaDirty for dirty check, but metaDirty becomes true once a range is read cached in the item. This does not look right?

14

Hmm, interesting. @leoluan can you find the exact commit which causes the problem (with git bisect maybe) and open a new issue on Github about this - thanks.

15

@ncw The exact commit when this tar problem started to occur was

and I opened an issue for this problem here. VFS mount: tar command gets warning messages of "file changed as we read it" for unchanging files · Issue #5277 · rclone/rclone · GitHub

2 Likes
16

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