Timestamps change on sftp backend when they shouldn't

What is the problem you are having with rclone?

When I mount a sftp backend, then open any file for viewing (e.g. a document) and then perform a rclone sync between that backend and another backend, the file is considered as modified.

What is your rclone version (output from rclone version)

$  rclone version
rclone v1.55.1
- os/type: linux
- os/arch: amd64
- go/version: go1.16.3
- go/linking: static
- go/tags: none

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

Linux Mint 20.1 64-bit

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

Hetzner Storage Box via sftp

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

rclone --dry-run -vv --progress sync sftp-backend: b2-backend:

The remote is mounted via systemd:

[Unit]
Description=Hetzner Storage Box - encrypted union
AssertPathIsDirectory=/mnt/rclone/sftp-crypt
After=network-online.target
Wants=network-online.target

[Service]
Type=simple
ExecStart=/usr/bin/rclone mount \
        --config=/root/.config/rclone/rclone.conf \
        --allow-other \
        --vfs-cache-mode full \
        --checksum \
        sftp-crypt:/ /mnt/rclone/sftp-crypt
ExecStop=/root/scripts/rclone_unmount.sh /mnt/rclone/sftp-crypt
Restart=always
RestartSec=10

[Install]
WantedBy=default.target

The rclone config contents with secrets removed.

[sftp-backend-01]
type = sftp
host = <sftp-host>
user = <sftp-user>
key_file = <sftp-key>
port = <sftp-port>
md5sum_command = md5 -r
sha1sum_command = sha1 -r

[sftp-backend-02]
type = sftp
host = <sftp-host2>
user = <sftp-user2>
port = <sftp-port2>
key_file = <sftp-key2>
md5sum_command = md5 -r
sha1sum_command = sha1 -r

[sftp-union]
type = union
upstreams = sftp-backend-01:data sftp-backend-02:data
action_policy = all
create_policy = all
search_policy = all

[sftp-crypt]
type = crypt
remote = sftp-union:crypt
password = <pwd>
password2 = <salt>

A log from the command with the -vv flag

2021-06-03 11:41:06 DEBUG : aaaaaaaaaa.csv: Size and modification time the same (differ by 0s, within tolerance 1s)
2021-06-03 11:41:06 DEBUG : aaaaaaaaaa.csv: Unchanged skipping
2021-06-03 11:41:06 DEBUG : bbbbbbbbbb.pdf: Size and modification time the same (differ by 2ms, within tolerance 1s)
2021-06-03 11:41:06 DEBUG : bbbbbbbbbb.pdf: Unchanged skipping
2021-06-03 11:41:06 DEBUG : test.txt: Modification times differ by -669h20m32.351s: 2021-06-03 11:39:10 +0200 CEST, 2021-05-06 12:18:37.649 +0000 UTC
2021-06-03 11:41:06 DEBUG : cccccccccc.pdf: Size and modification time the same (differ by 377ms, within tolerance 1s)
2021-06-03 11:41:06 DEBUG : cccccccccc.pdf: Unchanged skipping
2021-06-03 11:41:06 DEBUG : dddddddddd.pdf: Size and modification time the same (differ by 0s, within tolerance 1s)
2021-06-03 11:41:06 NOTICE: test.txt: Skipped copy as --dry-run is set (size 38)
2021-06-03 11:41:06 DEBUG : dddddddddd.pdf: Unchanged skipping

The file test.txt had a timestamp of 2021-05-06 12:18:37.649 +0000 UTC, but after I opened it in an editor and then closed it again, without saving the file, the timestamp changed to the "current timestamp" (i.e. the time when I opened the file).

I also attached a screenshot of the filemanagers where you can clearly see that the files in both locations had the exact same timestamp right before I opened it.

This only occurs with sftp and AFAIK only with the Hetzner Storage boxes. When using a Backblaze (B2) backend or a Wasabi (S3) backend then the timestamps don't change when opening a file for reading.
I also tested with 2 local linux servers as an encrypted sftp union backend and until now I couldn't reproduce this same behaviour.

So to summarize: an rclone sync works fine, incl correct timestamps, but as soon as I start opening files on the Hetzner storage boxes backend the files will have a different timestamp and therefore will be synced (while they shouldn't because they didn't actually change at all)

I'd guess the SFTP server is sending the wrong info back on the modtime, you can disable modtime:

https://rclone.org/sftp/#modified-time

Thanks, but will the timestamps be correct at all if I disable the modtime?

Also, after a copy or sync operation the timestamps are all correct. Does this mean that a mount calculates the timestamps in a different way than a copy or sync operation?

Best to give it a quick test and validate if that meets your needs or not.

Ok, I just tried and the issue remains.
Even worse, now I see the following error:

ERROR : Encrypted drive 'sftp-crypt:/': Statfs failed: this usage field is not supported

Take one file.

Check the modtime on it.

felix@gemini:~/test$ rclone lsl sftp:test/testfile -vv
2021/06/03 08:56:23 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/06/03 08:56:23 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "lsl" "sftp:test/testfile" "-vv"]
2021/06/03 08:56:23 DEBUG : Creating backend with remote "sftp:test/testfile"
2021/06/03 08:56:23 DEBUG : sftp://felix@localhost:22/test/testfile: New connection 127.0.0.1:43930->127.0.0.1:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.2"
2021/06/03 08:56:24 DEBUG : sftp://felix@localhost:22/test/testfile: Using absolute root directory "/home/felix/test/testfile"
2021/06/03 08:56:24 DEBUG : fs cache: adding new entry for parent of "sftp:test/testfile", "sftp:test"
        0 2021-06-03 08:55:14.000000000 testfile
2021/06/03 08:56:24 DEBUG : 11 go routines active

and open it up and run it again on that same file.

felix@gemini:~/test$ rclone lsl sftp:test/testfile -vv
2021/06/03 08:56:52 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2021/06/03 08:56:52 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "lsl" "sftp:test/testfile" "-vv"]
2021/06/03 08:56:52 DEBUG : Creating backend with remote "sftp:test/testfile"
2021/06/03 08:56:52 DEBUG : sftp://felix@localhost:22/test/testfile: New connection 127.0.0.1:43944->127.0.0.1:22 to "SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.2"
2021/06/03 08:56:52 DEBUG : sftp://felix@localhost:22/test/testfile: Using absolute root directory "/home/felix/test/testfile"
2021/06/03 08:56:52 DEBUG : fs cache: adding new entry for parent of "sftp:test/testfile", "sftp:test"
        5 2021-06-03 08:56:50.000000000 testfile
2021/06/03 08:56:52 DEBUG : 11 go routines active

I tried several times, but now the file's timestamp didn't change.

However, I did an rclone lsl on another file in another directory that I haven't accessed in a while and as can be seen in the output the timestamp is the current timestamp.
So I opened my filemanager and navigated to the folder where that file is located and to my surprise all 3 files in that folder now have the current timestamp!

$  rclone lsl sftp-crypt:dir/scans/2021-03-01/scan0007.PDF -vv
<7>DEBUG : Using config file from "/root/.config/rclone/rclone.conf"
<7>DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "lsl" "sftp-crypt:dir/scans/2021-03-01/scan0007.PDF" "-vv"]
<7>DEBUG : rclone: systemd logging support activated
<7>DEBUG : Creating backend with remote "sftp-crypt:dir/scans/2021-03-01/scan0007.PDF"
<7>DEBUG : Creating backend with remote "sftp-union:crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es"
<7>DEBUG : Creating backend with remote "sftp-backend-01:data"
<7>DEBUG : Creating backend with remote "sftp-backend-02:data"
<7>DEBUG : sftp://<user>@<host>:<port>/data: New connection <my-ip>:38950-><host-ip>:<host-port> to "SSH-2.0-OpenSSH_7.5 FreeBSD-20170903"
<7>DEBUG : sftp://<user>@<host>:<port>/data: New connection <my-ip>:57464-><host-ip>:<host-port> to "SSH-2.0-OpenSSH_7.5 FreeBSD-20170903"
<7>DEBUG : sftp://<user>@<host>:<port>/data: Using absolute root directory "/home/data"
<7>DEBUG : Creating backend with remote "sftp-backend-02:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es"
<7>DEBUG : sftp://<user>@<host>:<port>/data: Using absolute root directory "/home/data"
<7>DEBUG : sftp://<user>@<host>:<port>/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es: New connection <my-ip>:38954-><host-ip>:<host-port> to "SSH-2.0-OpenSSH_7.5 FreeBSD-20170903"
<7>DEBUG : Creating backend with remote "sftp-backend-01:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es"
<7>DEBUG : sftp://<user>@<host>:<port>/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es: Using absolute root directory "/home/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es"
<7>DEBUG : fs cache: adding new entry for parent of "sftp-backend-02:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es", "sftp-backend-02:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0"
<7>DEBUG : sftp://<user>@<host>:<port>/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es: New connection <my-ip>:57472-><host-ip>:<host-port> to "SSH-2.0-OpenSSH_7.5 FreeBSD-20170903"
<7>DEBUG : sftp://<user>@<host>:<port>/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es: Using absolute root directory "/home/data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es"
<7>DEBUG : fs cache: adding new entry for parent of "sftp-backend-01:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es", "sftp-backend-01:data/crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0"
<7>DEBUG : union root 'crypt/qpckqpsgr0i09n5teoiiafnl0k/dabb4gsg6desgbbn4kbgd9iads/fmrcpqlc9a151bjosknirrk3g0/82iod1ubap5pqrd9vo3lqhv5es': actionPolicy = *policy.All, createPolicy = *policy.All, searchPolicy = *policy.All
<7>DEBUG : scan0009.PDF: Excluded
<7>DEBUG : scan0008.PDF: Excluded
   655210 2021-06-03 15:53:53.000000000 scan0007.PDF
<7>DEBUG : 38 go routines active

As the foldername suggests the files should have a timestamp of 2021-03-01 and in my other rclone targets (B2, S3) this is the case, but after the rclone lsl on the sftp target all 3 files changed their modification time!

Edit: typo

So you can't recreate the issue?

Well, apparently the issue happens in different situations.
Sometimes it happens to a single file when just opening that file, sometimes it happens to all files in a folder when listing/accessing that folder, sometimes it happens to all files in a folder when I create a new file in that folder, sometimes it only happens to some files in a folder, ...

So yes, I can definitely recreate the issue, but there's unfortunately no golden rule for it.
One thing is for sure: wrong timestamps will appear for files I don't modify whenever I work for several hours on that sftp mount (and probably even faster than that).

It feels like you have something modifying the files though and updating the modtime.

If you can recreate something and give a way to do it, we can take a look and see what's going on.

Well it's definitely something out of my control, cfr timestamps that change when I run rclone lsl.

The way to recreate it is by setting up two Hetzner storage boxes, then setting up a union backend with those 2 boxes (over sftp), then creating a crypt remote over that union and then starting to play with the files inside of it.

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