--track-renames-strategy modtime doesn't work

Stpham · June 8, 2020, 4:23am

What is the problem you are having with rclone?

--track-renames-strategy modtime

Doesn't work

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

rclone-v1.52.0-031-gc4110780-beta-windows-amd64

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

Windows 10, 64 bit

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

Google Drive

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

rclone sync --track-renames --track-renames-strategy modtime --dry-run -v "F:\Cache\Test" "Google Drive:Test"

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

2020/06/08 10:08:52 INFO  : Google drive root 'Test': Making map for --track-renames
2020/06/08 10:08:52 INFO  : Google drive root 'Test': Finished making map for --track-renames
2020/06/08 10:08:52 NOTICE: newName.mkv: Not copying as --dry-run
2020/06/08 10:08:52 NOTICE: oldName.mkv: Not deleting as --dry-run
2020/06/08 10:08:52 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                29 / 29, 100%
Deleted:                1
Transferred:            1 / 1, 100%
Elapsed time:         0.0s

Note:

It's still work normal with --track-renames-strategy hash:

rclone sync --track-renames --track-renames-strategy hash --dry-run -v "F:\Cache\Test" "Google Drive:Test"
2020/06/08 10:08:03 INFO  : Google drive root 'Test': Making map for --track-renames
2020/06/08 10:08:03 INFO  : Google drive root 'Test': Finished making map for --track-renames
2020/06/08 10:08:04 NOTICE: oldName.mkv: Not moving as --dry-run
2020/06/08 10:08:04 INFO  : newName.mkv: Renamed from "oldName.mkv"
2020/06/08 10:08:04 INFO  : There was nothing to transfer
2020/06/08 10:08:04 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                29 / 29, 100%
Renamed:                1
Elapsed time:         0.0s

Animosity022 · June 8, 2020, 10:37am

Can you run the command with -vv?

felix@gemini:~/test$ rclone sync /home/felix/test gcrypt:test -vv --track-renames --track-renames-strategy modtime
2020/06/08 06:35:45 DEBUG : rclone: Version "v1.52.0" starting with parameters ["rclone" "sync" "/home/felix/test" "gcrypt:test" "-vv" "--track-renames" "--track-renames-strategy" "modtime"]
2020/06/08 06:35:45 DEBUG : Using config file from "/opt/rclone/rclone.conf"
2020/06/08 06:35:46 INFO  : Encrypted drive 'gcrypt:test': Making map for --track-renames
2020/06/08 06:35:46 INFO  : Encrypted drive 'gcrypt:test': Finished making map for --track-renames
2020/06/08 06:35:46 DEBUG : Encrypted drive 'gcrypt:test': Waiting for checks to finish
2020/06/08 06:35:46 DEBUG : Encrypted drive 'gcrypt:test': Waiting for renames to finish
2020/06/08 06:35:46 INFO  : new.mkv: Moved (server side)
2020/06/08 06:35:46 INFO  : test.mkv: Renamed from "new.mkv"
2020/06/08 06:35:46 DEBUG : Encrypted drive 'gcrypt:test': Waiting for transfers to finish
2020/06/08 06:35:46 DEBUG : Waiting for deletions to finish
2020/06/08 06:35:46 INFO  : There was nothing to transfer
2020/06/08 06:35:46 INFO  :
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                 2 / 2, 100%
Renamed:                1
Elapsed time:         0.4s

Works fine on my encrypted remote.

ncw · June 8, 2020, 4:48pm

Can you use rclone lsl on the file locally that you renamed and the file on drive so we can see the modtimes?

rclone lsl "F:\Cache\Test\newName.mkv"
rclone lsl "Google Drive:Test/oldName.mkv"

Can you re-run your command with the -vv flag please?

Stpham · June 10, 2020, 3:03am

This is result modtimes:

rclone lsl "F:\Cache\Test\newName.mkv"
118005929 2020-06-07 16:10:50.469591600 newName.mkv

rclone lsl "Google Drive:Test/oldName.mkv"
118005929 2020-06-07 16:10:50.469000000 oldName.mkv

Seen like it has a little different at the time: 16:10:50.469591600 vs 16:10:50.469000000

And this is the result of -vv:

2020/06/10 10:00:32 DEBUG : fs cache: renaming cache item "F:\\Cache\\Test" to be canonical "//?/F:/Cache/Test"
2020/06/10 10:00:33 INFO  : Google drive root 'Test': Making map for --track-renames
2020/06/10 10:00:33 INFO  : Google drive root 'Test': Finished making map for --track-renames
2020/06/10 10:00:33 DEBUG : Google drive root 'Test': Waiting for checks to finish
2020/06/10 10:00:33 DEBUG : Google drive root 'Test': Waiting for renames to finish
2020/06/10 10:00:33 DEBUG : Google drive root 'Test': Waiting for transfers to finish
2020/06/10 10:00:33 NOTICE: newName123.mkv: Not copying as --dry-run
2020/06/10 10:00:33 DEBUG : Waiting for deletions to finish
2020/06/10 10:00:33 NOTICE: oldName.mkv: Not deleting as --dry-run
2020/06/10 10:00:33 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                 2 / 2, 100%
Deleted:                1
Transferred:            1 / 1, 100%
Elapsed time:         0.0s

2020/06/10 10:00:33 DEBUG : 4 go routines active

nle · June 10, 2020, 8:57am

You could look at the --modify-window flag

ncw · June 10, 2020, 8:59am

I've managed to replicate this problem.

It has exposed a fundamental flaw in the scheme which I'm having a think about how to fix!

ncw · June 10, 2020, 10:06am

OK I spent some time thinking about this and I've come up with a fix.

The old method of attempting to hash the times has a fatal flaw in that two arbitrarily close times could hash to the same value. This fix checks all the times. This is hashed on size of file so provided you aren't renaming lots of identically sized files will be efficient.

Can you have a go with this?

https://beta.rclone.org/branch/v1.52.0-039-g6d4533fe-fix-trs-modtime-beta/ (uploaded in 15-30 mins)

Stpham · June 12, 2020, 2:19am

I was test on v1.52.0-039-g6d4533fe-fix-trs-modtime-beta and modtime work normal now.

MINGW64 ~/Downloads/rclone-v1.52.0-039-g6d4533fe-fix-trs-modtime-beta-windows-amd64
$ ./rclone sync --track-renames --track-renames-strategy modtime -vv "F:\Cache\Test" "Google Drive:Test"

2020/06/12 09:13:04 DEBUG : fs cache: renaming cache item "F:\\Cache\\Test" to be canonical "//?/F:/Cache/Test"
2020/06/12 09:13:06 INFO  : Google drive root 'Test': Making map for --track-renames
2020/06/12 09:13:06 INFO  : Google drive root 'Test': Finished making map for --track-renames
2020/06/12 09:13:06 DEBUG : Google drive root 'Test': Waiting for checks to finish
2020/06/12 09:13:06 DEBUG : Google drive root 'Test': Waiting for renames to finish
2020/06/12 09:13:07 INFO  : oldName.mkv: Moved (server side)
2020/06/12 09:13:07 INFO  : newName.mkv: Renamed from "oldName.mkv"
2020/06/12 09:13:07 DEBUG : Google drive root 'Test': Waiting for transfers to finish
2020/06/12 09:13:07 DEBUG : Waiting for deletions to finish
2020/06/12 09:13:07 INFO  : There was nothing to transfer
2020/06/12 09:13:07 INFO  :
Transferred:             0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:                 2 / 2, 100%
Renamed:                1
Elapsed time:         0.8s

2020/06/12 09:13:07 DEBUG : 4 go routines active

But when I test on rclone-v1.52.1-windows-amd64, it still doesn't work

ncw · June 12, 2020, 2:39pm

Great

Despite the name it isn't merged to that yet

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

an531 · July 13, 2020, 7:10pm

I wanted to add that I just tried --track-renames --track-renames-strategy modtime and the process never finishes. Upon inspection, the log just repeats the last set of information ad infinitum. I gave up after an hour...

Commands used

rclone sync remote1: remote2: --transfers 16 --backup-dir remote2:\bkp --log-file=C:\log.txt --log-level DEBUG --track-renames --track-renames-strategy modtime -n

Rclone version

rclone v1.52.2-212-g80d2f381-beta 
os/arch windows/amd64
go version: go1.14.4

Last part of the log

020/07/13 18:38:51 DEBUG : Encrypted drive 'remote2:': Waiting for checks to finish
2020/07/13 18:38:51 DEBUG : Encrypted drive 'remote2:': Waiting for renames to finish
2020/07/13 18:39:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:40:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:41:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:42:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:43:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:44:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:45:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:46:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:47:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:48:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:49:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:50:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:51:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:52:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:53:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:54:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:55:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:56:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:57:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:58:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 18:59:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:00:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:01:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:02:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:03:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:04:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:05:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:06:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:07:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:08:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:09:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:10:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:11:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:12:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:13:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:14:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:15:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:16:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:17:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:18:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:19:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:20:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:21:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:22:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:23:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:24:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:25:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

2020/07/13 19:26:10 INFO  : 
Transferred:   	         0 / 0 Bytes, -, 0 Bytes/s, ETA -
Checks:              3353 / 3353, 100%
Transferred:           28 / 28, 100%
Elapsed time:         0.1s

Later I thought that perhaps the new flag doesn't play well with -n. However, without it the log stops being updated at some point and the command prompt is stuck (it's not updating elapsed time, but it's not unresponsive). The expected changes didn't happen on the remote.

ncw · July 14, 2020, 1:42pm

Hmm, that sounds like it might be a deadlock...

Can you kill -QUIT the process and paste the backtrace generated here and I'll take a look.

an531 · July 14, 2020, 1:57pm

To get the job done, I renamed the main folders myself, run the commands on smaller subdirectories first and run the main operation several times. It seems to be making progress on each run, although it gets stuck in random places. Also, it created duplicate directories, although it might be due to the fact that I had to cancel the stuck operations (and perhaps rclone would delete those later).

Currently, rclone is in the process of transferring some files to the problematic remote, so if I face the problem again I will follow your instructions and report back later. I created a separate topic about this, but perhaps it'll be better to just continue here.

an531 · July 15, 2020, 9:51am

Okay, it's happening again... How do I kill -QUIT a process and generate a backtrace on Windows (7 x64)?

ncw · July 15, 2020, 12:44pm

Ah, I don't know how to do this on Windows

An alternate method is to run with --rc and when the problem happens go to http://localhost:5572/debug/pprof/goroutine?debug=1 in your browser

That will show a list of running go routines.

an531 · July 15, 2020, 12:55pm

Is this it?

Web browser output

goroutine profile: total 19
8 @ 0x43c2e5 0x44cd0e 0x44ccf9 0x44ca5e 0x47a043 0x14bc70d 0x14bc247 0x14bcb9b 0x14ba157 0x46a9c1
# 0x44ca5d sync.runtime_SemacquireMutex + 0x4d runtime / sema.go: 71
# 0x47a042 sync. (* Mutex) .lockSlow + 0x102 sync / mutex.go: 138
# 0x14bc70c sync. (* Mutex) .Lock + 0x4fc sync / mutex.go: 81
# 0x14bc246 github.com/rclone/rclone/fs/sync.(*syncCopyMove).popRenameMap+0x36 github.com/rclone/rclone/fs/sync/sync.go:660
# 0x14bcb9a github.com/rclone/rclone/fs/sync.(*syncCopyMove).tryRename+0x17a github.com/rclone/rclone/fs/sync/sync.go:749
# 0x14ba156 github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairRenamer+0xe6 github.com/rclone/rclone/fs/sync/sync.go:346

4 @ 0x43c2e5 0x44c1a8 0x14b6afb 0x14ba2ef 0x46a9c1
# 0x14b6afa github.com/rclone/rclone/fs/sync.(*pipe).GetMax+0xea github.com/rclone/rclone/fs/sync/pipe.go:124
# 0x14ba2ee github.com/rclone/rclone/fs/sync.(*syncCopyMove).pairCopyOrMove+0xbe github.com/rclone/rclone/fs/sync/sync.go:361

1 @ 0x43c2e5 0x407535 0x4071eb 0xac2c85 0x46a9c1
# 0xac2c84 github.com/rclone/rclone/fs/march.(*March).Run.func2+0x54 github.com/rclone/rclone/fs/march/march.go:199

1 @ 0x43c2e5 0x432fc1 0x4324bc 0x4e9cec 0x4eb071 0x4ee9c9 0x4eec7f 0x521cdb 0x53ceb9 0x53b81b 0x7371d4 0x804668 0x46a9c1
# 0x4324bb internal / poll.runtime_pollWait + 0x5b runtime / netpoll.go: 203
# 0x4e9ceb internal / poll. (* PollDesc) .wait + 0x4b internal / poll / fd_poll_runtime.go: 87
# 0x4eb070 internal / poll. (* IoSrv) .ExecIO + 0x120 internal / poll / fd_windows.go: 228
# 0x4ee9c8 internal / poll. (* FD) .acceptOne + 0xa8 internal / poll / fd_windows.go: 896
# 0x4eec7e internal / poll. (* FD). Accept + 0x15e internal / poll / fd_windows.go: 930
# 0x521cda net. (* NetFD) .accept + 0x7a net / fd_windows.go: 193
# 0x53ceb8 net. (* TCPListener) .accept + 0x38 net / tcpsock_posix.go: 139
# 0x53b81a net. (* TCPListener) .Accept + 0x6a net / tcpsock.go: 261
# 0x7371d3 net / http. (* Server) .Serve + 0x263 net / http / server.go: 2901
# 0x804667 github.com/rclone/rclone/cmd/serve/httplib.(*Server).Serve.func1+0x457 github.com/rclone/rclone/cmd/serve/httplib/httplib.go:351

1 @ 0x43c2e5 0x44c1a8 0x1463744 0x46a9c1
# 0x1463743 github.com/rclone/rclone/cmd.startProgress.func2+0x123 github.com/rclone/rclone/cmd/progress.go:48

1 @ 0x43c2e5 0x44c1a8 0xc152e7 0x46a9c1
# 0xc152e6 github.com/rclone/rclone/vendor/go.opencensus.io/stats/view.(*worker).start+0x106 github.com/rclone/rclone/vendor/go.opencensus.io/stats/view/ worker.go: 276

1 @ 0x43c2e5 0x44cd0e 0x44ccf9 0x44c939 0x47bb5b 0x14ba9c7 0x14bd32d 0x14bec3b 0x15ca416 0x15ca3cd 0x145e25d 0x15ca360 0x144e1b4 0x144aa 0x14601bx 0x1460589
# 0x44c938 sync.runtime_Semacquire + 0x48 runtime / sema.go: 56
# 0x47bb5a sync. (* WaitGroup) .Wait + 0x6a sync / waitgroup.go: 130
# 0x14ba9c6 github.com/rclone/rclone/fs/sync.(*syncCopyMove).stopRenamers+0x76 github.com/rclone/rclone/fs/sync/sync.go:426
# 0x14bd32c github.com/rclone/rclone/fs/sync.(*syncCopyMove).run+0x33c github.com/rclone/rclone/fs/sync/sync.go:830
# 0x14bec3a github.com/rclone/rclone/fs/sync.runSyncCopyMove+0x26a github.com/rclone/rclone/fs/sync/sync.go:1042
# 0x15ca415 github.com/rclone/rclone/fs/sync.Sync+0x95 github.com/rclone/rclone/fs/sync/sync.go:1047
# 0x15ca3cc github.com/rclone/rclone/cmd/sync.glob..func1.1+0x4c github.com/rclone/rclone/cmd/sync/sync.go:55
# 0x145e25c github.com/rclone/rclone/cmd.Run+0xcc github.com/rclone/rclone/cmd/cmd.go:242
# 0x15ca35f github.com/rclone/rclone/cmd/sync.glob..func1+0x12f github.com/rclone/rclone/cmd/sync/sync.go:53
# 0x144e1b3 github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).execute+0x2a3 github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go: 846
# 0x144ee9f github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).ExecuteC+0x34f github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go: 950
# 0x1460588 github.com/rclone/rclone/vendor/github.com/spf13/cobra.(*Command).Execute+0x98 github.com/rclone/rclone/vendor/github.com/spf13/cobra/command.go: 887
# 0x1460579 github.com/rclone/rclone/cmd.Main+0x89 github.com/rclone/rclone/cmd/cmd.go:514
# 0x15d1b06 main.main + 0x26 github.com/rclone/rclone/rclone.go:14
# 0x43bf29 runtime.main + 0x1f9 runtime / proc.go: 203

1 @ 0x72c761 0x46a9c1
# 0x72c760 net / http. (* ConnReader) .backgroundRead + 0x0 net / http / server.go: 677

1 @ 0x7ee0bc 0x7eded7 0x7eabf1 0x7f8291 0x7f8cfc 0x7338eb 0x7358ac 0x736e2a 0x7326d3 0x46a9c1
# 0x7ee0bb runtime / pprof.writeRuntimeProfile + 0x9b runtime / pprof / pprof.go: 694
# 0x7eded6 runtime / pprof.writeGoroutine + 0xa6 runtime / pprof / pprof.go: 656
# 0x7eabf0 runtime / pprof. (* Profile) .WriteTo + 0x3e0 runtime / pprof / pprof.go: 329
# 0x7f8290 net / http / pprof.handler.ServeHTTP + 0x340 net / http / pprof / pprof.go: 248
# 0x7f8cfb net / http / pprof.Index + 0x73b net / http / pprof / pprof.go: 271
# 0x7338ea net / http.HandlerFunc.ServeHTTP + 0x4a net / http / server.go: 2012
# 0x7358ab net / http. (* ServeMux) .ServeHTTP + 0x1ab net / http / server.go: 2387
# 0x736e29 net / http.serverHandler.ServeHTTP + 0xa9 net / http / server.go: 2807
# 0x7326d2 net / http. (* Conn) .serve + 0x872 net / http / server.go: 1895

Command run

rclone sync "localpath:\" "remote:\" --backup-dir remote:\bkp --log-file=C:\log.txt -vv --track-renames --track-renames-strategy modtime -P -n --rc

If this isn't enough I could install WinDbg and try to get the information you need. However, since I've never debugged a program before, it would be helpful to know what to look for. I imagine it would involve creating a process dump (or minidump) and opening it with WinDbg.

ncw · July 15, 2020, 2:07pm

That is exactly what I wanted - thank you!

I can see I made a locking error which is causing --track-renames-strategy modtime to lock up sometimes.

Try this

v1.52.2-215-g81716d30-fix-track-renames-deadlock-beta on branch fix-track-renames-deadlock (uploaded in 15-30 mins)

an531 · July 15, 2020, 2:59pm

The dry run completed without any problems. The actual sync is now in progress and I will double check the results when it's finished (in 14h ). Thank you very much for your help with this, Nick!

If you ever need to idiot-proof some new features or just someone to test new builds for W7 x64 (or W10), then I'm your guy. Unfortunately, I don't know how to use github yet (when it comes to bug reports, branches etc.), but will try to find a guide later.

You are awesome.

ncw · July 15, 2020, 3:02pm

Great! Look forward to the result.

The mistake in the code was very obvious so I think this will fix it

Thanks for the offer and the praise!

system · September 14, 2020, 11:02am

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