Bug: without --modify-window=1s sync to :crypt: always copies all files

hyperknot · September 7, 2021, 1:31pm

What is the problem you are having with rclone?

I'd like to use rclone exactly like rsync to sync directories locally. My problem is that it always overwrites all files with Copied (replaced existing).

Actually, it's really strange, it even does this in the initial run, when the destination folder is empty. In the initial run I can see a lot of lines with Copied (replaced existing).

I'm using the crypt module.

I think there is a bug with the sub 1 seconds times here (see log). Source folder is APFS destination if external USB drive with HFS+.

In the docs I read this:

For example OS X only stores modification times to the nearest second so if you are reading and writing to an OS X filing system this will be 1s by default.

What is your rclone version (output from `rclone version`)

rclone v1.56.0
- os/version: darwin 11.5.2 (64 bit)
- os/kernel: 20.6.0 (x86_64)
- os/type: darwin
- os/arch: amd64
- go/version: go1.16.6
- go/linking: dynamic
- go/tags: none

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

Local HDD.

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


CRYPT_KEY=xxx
CRYPT_PASSWORD=$(rclone obscure $CRYPT_KEY)



rclone sync \
  --config=/dev/null \
  --crypt-remote /Volumes/.../backup_enc \
  --crypt-filename-encryption=off \
  --crypt-directory-name-encryption=false \
  --crypt-password "$CRYPT_PASSWORD" \
  --drive-use-trash=false \
  -v \
  --stats=10s \
  --skip-links \
  --transfers=1 \
  --checkers=1 \
  --max-backlog=100 \
  --filter-from filter.txt \
  "$HOME" :crypt:

The rclone config contents with secrets removed.

no config used

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

2021/09/07 15:30:01 DEBUG : Library/Preferences/com.getdropbox.dropbox.plist: Modification times differ by -611.246712ms: 2020-06-29 18:50:33.611246712 +0200 CEST, 2020-06-29 18:50:33 +0200 CEST
2021/09/07 15:30:01 DEBUG : Library/Preferences/com.getdropbox.dropbox.plist: md5 = e65388b56c6935f85fd25b86c72c8f3b OK
2021/09/07 15:30:01 INFO  : Library/Preferences/com.getdropbox.dropbox.plist: Copied (replaced existing)

hyperknot · September 7, 2021, 1:35pm

I can confirm that by adding --modify-window=1s the problem is fixed. So it is a bug.

the host is macOS
the source is the internal SSD with APFS
the destination is external USB with HFS+

Animosity022 · September 7, 2021, 1:36pm

It's not a bug.

Some file systems don't report down low enough level so you need to compensate for that as you found out.

hyperknot · September 7, 2021, 2:48pm

I don't understand, for me the part below tells the opposite. It seems to me that --modify-window=1s is supposed to be applied on macOS but it is not.

For example OS X only stores modification times to the nearest second so if you are reading and writing to an OS X filing system this will be 1s by default.

Animosity022 · September 7, 2021, 2:51pm

You'd have to share a full debug log as I can't see your screen.

hyperknot · September 7, 2021, 4:24pm

OK, I made a minimal reproducible case and I can also confirm that this is related to the :crypt: destination.

Bug: when using :crypt: the automatic --modify-window=1s is not applied on macOS filesystems.

Minimal test case:

rm -rf temp
mkdir temp
touch temp/a.txt

CRYPT_KEY=x
CRYPT_PASSWORD=$(rclone obscure $CRYPT_KEY)

rclone sync \
  --config=/dev/null \
  -vv \
  --crypt-remote /Volumes/x/temp \
  --crypt-password "$CRYPT_PASSWORD" \
  temp :crypt:

log:

2021/09/07 18:30:06 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "sync" "--config=/dev/null" "-vv" "--crypt-remote" "/Volumes/x/temp" "--crypt-password" "cab3PCqQwvWaomoJptDypj4" "temp" ":crypt:"]
2021/09/07 18:30:06 DEBUG : Creating backend with remote "temp"
2021/09/07 18:30:06 DEBUG : Using config file from ""
2021/09/07 18:30:06 DEBUG : fs cache: renaming cache item "temp" to be canonical "/Users/x/temp"
2021/09/07 18:30:06 DEBUG : Creating backend with remote ":crypt:"
2021/09/07 18:30:06 DEBUG : :crypt: detected overridden config - adding "{XPqzC}" suffix to name
2021/09/07 18:30:06 DEBUG : Creating backend with remote "/Volumes/x/temp"
2021/09/07 18:30:06 DEBUG : fs cache: renaming cache item ":crypt:" to be canonical ":crypt{XPqzC}:"
2021/09/07 18:30:06 DEBUG : Encrypted drive ':crypt{XPqzC}:': Waiting for checks to finish
2021/09/07 18:30:06 DEBUG : a.txt: Modification times differ by -414.76297ms: 2021-09-07 18:26:15.41476297 +0200 CEST, 2021-09-07 18:26:15 +0200 CEST
2021/09/07 18:30:06 DEBUG : Encrypted drive ':crypt{XPqzC}:': Waiting for transfers to finish
2021/09/07 18:30:06 DEBUG : a.txt: md5 = 8b4a11dd0f6d6479a622c3eb428b8d83 OK
2021/09/07 18:30:06 INFO  : a.txt: Copied (replaced existing)
2021/09/07 18:30:06 DEBUG : Waiting for deletions to finish
2021/09/07 18:30:06 INFO  :
Transferred:             32 / 32 Byte, 100%, 0 Byte/s, ETA -
Checks:                 1 / 1, 100%
Transferred:            1 / 1, 100%
Elapsed time:         0.1s

2021/09/07 18:30:06 DEBUG : 5 go routines active

hyperknot · September 7, 2021, 4:25pm

I renamed the topic and moved to bug.

Animosity022 · September 7, 2021, 4:26pm

The default is 1ns(nanosecond) not 1s(second).

      --modify-window duration               Max time diff to be considered the same (default 1ns)

hyperknot · September 7, 2021, 4:27pm

No, it is 1s when macOS filesystem is detected.

Animosity022 · September 7, 2021, 4:28pm

Where do you see that?

etexter@seraphite Downloads % rclone copy test test2 -vv
2021/09/07 12:28:12 DEBUG : Using config file from "/Users/etexter/.config/rclone/rclone.conf"
2021/09/07 12:28:12 DEBUG : rclone: Version "v1.55.1" starting with parameters ["rclone" "copy" "test" "test2" "-vv"]
2021/09/07 12:28:12 DEBUG : Creating backend with remote "test"
2021/09/07 12:28:12 DEBUG : fs cache: adding new entry for parent of "test", "/Users/etexter/Downloads"
2021/09/07 12:28:12 DEBUG : Creating backend with remote "test2"
2021/09/07 12:28:12 DEBUG : fs cache: renaming cache item "test2" to be canonical "/Users/etexter/Downloads/test2"
2021/09/07 12:28:12 DEBUG : test: Size and modification time the same (differ by 0s, within tolerance 1ns)
2021/09/07 12:28:12 DEBUG : test: Unchanged skipping
2021/09/07 12:28:12 INFO  :
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:         0.0s

2021/09/07 12:28:12 DEBUG : 4 go routines active
etexter@seraphite Downloads % rclone version
rclone v1.55.1
- os/type: darwin
- os/arch: arm64
- go/version: go1.16.3
- go/linking: dynamic
- go/tags: cmount

hyperknot · September 7, 2021, 4:31pm

Here is the log without :crypt::

2021/09/07 18:31:37 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "sync" "--config=/dev/null" "-vv" "temp" "/Volumes/Blue/temp"]
2021/09/07 18:31:37 DEBUG : Creating backend with remote "temp"
2021/09/07 18:31:37 DEBUG : Using config file from ""
2021/09/07 18:31:37 DEBUG : fs cache: renaming cache item "temp" to be canonical "/Users/user/Documents/dev/temp/temp"
2021/09/07 18:31:37 DEBUG : Creating backend with remote "/Volumes/Blue/temp"
2021/09/07 18:31:37 DEBUG : Local file system at /Volumes/Blue/temp: Waiting for checks to finish
2021/09/07 18:31:37 DEBUG : a.txt: Modification times differ by -414.76297ms: 2021-09-07 18:26:15.41476297 +0200 CEST, 2021-09-07 18:26:15 +0200 CEST
2021/09/07 18:31:37 DEBUG : a.txt: md5 = d41d8cd98f00b204e9800998ecf8427e OK
2021/09/07 18:31:37 INFO  : a.txt: Updated modification time in destination
2021/09/07 18:31:37 DEBUG : a.txt: Unchanged skipping
2021/09/07 18:31:37 DEBUG : Local file system at /Volumes/Blue/temp: Waiting for transfers to finish
2021/09/07 18:31:37 DEBUG : Waiting for deletions to finish
2021/09/07 18:31:37 INFO  : There was nothing to transfer
2021/09/07 18:31:37 INFO  :
Transferred:   	          0 / 0 Byte, -, 0 Byte/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:         0.0s

2021/09/07 18:31:37 DEBUG : 4 go routines active

Animosity022 · September 7, 2021, 4:33pm

Where do you see that it would be 1 second for MacOS only?

Your test there supports that it is 1ns.

hyperknot · September 7, 2021, 4:47pm

Without crypt it only updates the file time, but does nothing else. With crypt it always overwrites all files.

I don't know what source file is the relevant here, but probably this:

	// Default precision of 1s
	precision = time.Second

github.com

rclone/rclone/blob/2bc2546d5c93d8a34361e546279e991986090c3f/backend/local/local.go#L607-L657

    
      
          // Read the precision
          func (f *Fs) readPrecision() (precision time.Duration) {
          	// Default precision of 1s
          	precision = time.Second
          
          
	// Create temporary file and test it
          	fd, err := ioutil.TempFile("", "rclone")
          	if err != nil {
          		// If failed return 1s
          		// fmt.Println("Failed to create temp file", err)
          		return time.Second
          	}
          	path := fd.Name()
          	// fmt.Println("Created temp file", path)
          	err = fd.Close()
          	if err != nil {
          		return time.Second
          	}
          
          
	// Delete it on return

This file has been truncated. show original

Animosity022 · September 7, 2021, 4:55pm

I think you are confusing a few things.

For 1 second, it's referring to the OS running:

Rclone reads and writes the modified time using an accuracy determined by the OS. Typically this is 1ns on Linux, 10 ns on Windows and 1 Second on OS X.

On MacOS, I only get the second reported back:

etexter@seraphite Downloads % stat test
16777233 20953815 -rw-r--r-- 1 etexter staff 0 0 "Sep  7 12:28:01 2021" "Sep  7 12:28:01 2021" "Sep  7 12:28:01 2021" "Sep  7 12:28:01 2021" 4096 0 0 test

On Linux, I get down to the ns.

felix@gemini:~$ touch test
felix@gemini:~$ stat test
  File: test
  Size: 4096      	Blocks: 8          IO Block: 4096   directory
Device: 802h/2050d	Inode: 25174527    Links: 2
Access: (0775/drwxrwxr-x)  Uid: ( 1000/   felix)   Gid: ( 1000/   felix)
Access: 2021-09-07 12:53:55.593514739 -0400
Modify: 2021-09-07 12:53:55.593514739 -0400
Change: 2021-09-07 12:53:55.593514739 -0400
 Birth: 2021-09-06 11:07:47.170834402 -0400

Rclone operations default to check for times with a tolerance of 1ns.

If you want to adjust that to second, you can add the flag:

--modify-window 1s

and that would fix your thing.

hyperknot · September 7, 2021, 4:59pm

OK, but the crypt bug is still present.

Without crypt, without --modify-window=1s: no copy but update times
Without crypt, with --modify-window=1s: no operations

With crypt, without --modify-window=1s: always re-copy all files
With crypt, with --modify-window=1s: no operations

hyperknot · September 7, 2021, 5:01pm

I think there is a bug in there somewhere, as modify window should be the max of the fs precisions.

github.com

rclone/rclone/blob/2bc2546d5c93d8a34361e546279e991986090c3f/fs/fs.go#L75-L91

    
      
          // GetModifyWindow calculates the maximum modify window between the given Fses
          // and the Config.ModifyWindow parameter.
          func GetModifyWindow(ctx context.Context, fss ...Info) time.Duration {
          	window := GetConfig(ctx).ModifyWindow
          	for _, f := range fss {
          		if f != nil {
          			precision := f.Precision()
          			if precision == ModTimeNotSupported {
          				return ModTimeNotSupported
          			}
          			if precision > window {
          				window = precision
          			}
          		}
          	}
          	return window
          }

hyperknot · September 7, 2021, 5:20pm

OK, I found it, the bug is in

github.com

rclone/rclone/blob/2bc2546d5c93d8a34361e546279e991986090c3f/backend/local/local.go#L607-L657

    
      
          // Read the precision
          func (f *Fs) readPrecision() (precision time.Duration) {
          	// Default precision of 1s
          	precision = time.Second
          
          
	// Create temporary file and test it
          	fd, err := ioutil.TempFile("", "rclone")
          	if err != nil {
          		// If failed return 1s
          		// fmt.Println("Failed to create temp file", err)
          		return time.Second
          	}
          	path := fd.Name()
          	// fmt.Println("Created temp file", path)
          	err = fd.Close()
          	if err != nil {
          		return time.Second
          	}
          
          
	// Delete it on return

This file has been truncated. show original

This function always creates a test file at host's temp folder. On macOS it is in /var/folders/... which on recent macOS always means APFS, and APFS has a 1ns precision.

This function totally doesn't check the actual filesystem, it only checks the host's temp folder. This is probably a universal bug, unrelated to macOS.

Animosity022 · September 7, 2021, 5:25pm

With a crypt local remote on my Mac.

etexter@seraphite crypt % rclone copy /etc/hosts TC: -vv
2021/09/07 13:25:01 DEBUG : rclone: Version "v1.56.0" starting with parameters ["rclone" "copy" "/etc/hosts" "TC:" "-vv"]
2021/09/07 13:25:01 DEBUG : Creating backend with remote "/etc/hosts"
2021/09/07 13:25:01 DEBUG : Using config file from "/Users/etexter/.config/rclone/rclone.conf"
2021/09/07 13:25:01 DEBUG : fs cache: adding new entry for parent of "/etc/hosts", "/etc"
2021/09/07 13:25:01 DEBUG : Creating backend with remote "TC:"
2021/09/07 13:25:01 DEBUG : Creating backend with remote "/Users/etexter/Downloads/crypt"
2021/09/07 13:25:01 DEBUG : hosts: Size and modification time the same (differ by 0s, within tolerance 1ns)
2021/09/07 13:25:01 DEBUG : hosts: Unchanged skipping
2021/09/07 13:25:01 INFO  :
Transferred:   	          0 / 0 Byte, -, 0 Byte/s, ETA -
Checks:                 1 / 1, 100%
Elapsed time:         0.0s

2021/09/07 13:25:01 DEBUG : 4 go routines active

Works fine for me.

hyperknot · September 7, 2021, 5:31pm

I found the bug, created a bug report. Try it on an external non-APFS drive.

github.com/rclone/rclone

local filesystem's precision it not tested correctly

opened 05:29PM - 07 Sep 21 UTC

hyperknot

#### The associated forum post URL from `https://forum.rclone.org` https://foru…m.rclone.org/t/bug-when-using-the-automatic-modify-window-1s-is-not-applied-on-macos-filesystems/26394 #### What is the problem you are having with rclone? local.go / readPrecision() is testing the wrong filesystem. It always tests the host's tmp folder, which is totally unrelated to the filesystems being used for the operations. For example on recent macOS, it always returns 1ns as the root fs is always APFS these days. This means that sync operations to external drives will break if those drives are non-APFS, as seen in the forum where crypt always copies everything. The problem is very clear in the source, the test file is always created in the system's temp folder. https://github.com/rclone/rclone/blob/2bc2546d5c93d8a34361e546279e991986090c3f/backend/local/local.go#L608 #### What is your rclone version (output from `rclone version`) master #### Which OS you are using and how many bits (e.g. Windows 7, 64 bit) macOS Big Sur #### Which cloud storage system are you using? (e.g. Google Drive) local, external USB drive #### The command you were trying to run (e.g. `rclone copy /tmp remote:tmp`) Detailed commands in forum. #### A log from the command with the `-vv` flag (e.g. output from `rclone -vv copy /tmp remote:tmp`) Detailed logs in forum. #### How to use GitHub * Please use the 👍 [reaction](https://blog.github.com/2016-03-10-add-reactions-to-pull-requests-issues-and-comments/) to show that you are affected by the same issue. * Please don't comment if you have no relevant information to add. It's just extra noise for everyone subscribed to this issue. * Subscribe to receive notifications on status change and new comments.

Animosity022 · September 7, 2021, 5:32pm

Formatted as what?

Bug: without --modify-window=1s sync to :crypt: always copies all files

What is the problem you are having with rclone?

What is your rclone version (output from rclone version)

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

What is your rclone version (output from `rclone version`)

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

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