Core/transferred reports duplicate (triplicate) records for move operations

OS: Windows 10 x64
rclone: v1.51.0-125-g32df634c-beta

I am moving files and folders between remotes via rclone rc. To be specific, one remote is OneDrive and another is my local disk:

[onedrive]
type = onedrive
token = HERE-GOES-TOKEN
drive_type = personal

[disk]
type = local

When I check the list of transfers using /core/transferred, it reports triplicate records (so the same transfer is listed 3 times).

This happens after /operations/movefile and /sync/move commands. Commands /operations/copyfile and /sync/copy do not cause that.

Example of /operations/movefile:

http://127.0.0.1:5572/operations/movefile
{"srcFs":"disk:/path/to/some/folder/","srcRemote":"another.txt","dstFs":"onedrive:/another/path/to/some/folder/","dstRemote":"another.txt"}

http://127.0.0.1:5572/core/transferred
{
    "transferred": [
        {
            "bytes": 0,
            "checked": true,
            "completed_at": "2020-03-22T14:12:00.2847287+01:00",
            "error": "",
            "group": "job/368",
            "name": "another.txt",
            "size": 6,
            "started_at": "2020-03-22T14:11:58.9134588+01:00"
        },
        {
            "bytes": 6,
            "checked": false,
            "completed_at": "2020-03-22T14:12:00.2847287+01:00",
            "error": "",
            "group": "job/368",
            "name": "another.txt",
            "size": 6,
            "started_at": "2020-03-22T14:11:58.9134588+01:00"
        },
        {
            "bytes": 0,
            "checked": true,
            "completed_at": "2020-03-22T14:12:00.2847287+01:00",
            "error": "",
            "group": "job/368",
            "name": "another.txt",
            "size": 6,
            "started_at": "2020-03-22T14:12:00.2847287+01:00"
        }
    ]
}

As you can see, it's an absolutely identical record being reported 3 times.

Example of /sync/move (folder contains only one file - single-file.txt):

http://127.0.0.1:5572/sync/move
{"srcFs":"disk:/path/to/different/folder","dstFs":"onedrive:/another/path/to/different/folder","deleteEmptySrcDirs":"true"}

http://127.0.0.1:5572/core/transferred
{
    "transferred": [
        {
            "bytes": 0,
            "checked": true,
            "completed_at": "2020-03-22T14:06:54.7664079+01:00",
            "error": "",
            "group": "job/40",
            "name": "single-file.txt",
            "size": 15,
            "started_at": "2020-03-22T14:06:52.4745278+01:00"
        },
        {
            "bytes": 15,
            "checked": false,
            "completed_at": "2020-03-22T14:06:54.7664079+01:00",
            "error": "",
            "group": "job/40",
            "name": "single-file.txt",
            "size": 15,
            "started_at": "2020-03-22T14:06:52.4745278+01:00"
        },
        {
            "bytes": 0,
            "checked": true,
            "completed_at": "2020-03-22T14:06:54.7664079+01:00",
            "error": "",
            "group": "job/40",
            "name": "single-file.txt",
            "size": 15,
            "started_at": "2020-03-22T14:06:54.7664079+01:00"
        }
    ]
}

That looks like a bug to me.

For comparison, here's the output after /sync/copy command (folder contains only one file - lastfile.txt):

http://127.0.0.1:5572/sync/copy
{"srcFs":"disk:/path/to/some/other","dstFs":"onedrive:/path/to/other/folder"}

http://127.0.0.1:5572/core/transferred
{
    "transferred": [
         {
            "bytes": 13,
            "checked": false,
            "completed_at": "2020-03-22T14:14:13.5548747+01:00",
            "error": "",
            "group": "job/505",
            "name": "lastfile.txt",
            "size": 13,
            "started_at": "2020-03-22T14:14:10.8200743+01:00"
        }
    ]
}

Note that two of the records have checked = true so that is rclone checking it needs to do the transfer before doing it.

I'm not sure why there are two checks - are you using --backup-dir maybe?

1 Like

that is rclone checking it needs to do the transfer before doing it.

Why there are no such checks for copy operations?

are you using --backup-dir maybe?

No, I don't use this flag. Here's the full list of options (dot . is the current directory from which I serve web GUI):

rclone rcd --transfers 1 --rc-user USERNAME --rc-pass PASSWORD .

Can you share a log with -vv of the operation? That might shed some light as to what is going on.

Yes, sorry, should have done it from the beginning:

Verbose log
$ /d/temp/rclone-beta/rclone.exe rcd -vv --transfers 1 --rc-user USERNAME --rc-pass PASSWORD .
2020/03/23 11:36:52 DEBUG : rclone: Version "v1.51.0-125-g32df634c-beta" starting with parameters ["D:\\temp\\rclone-beta\\rclone.exe" "rcd" "-vv" "--transfers" "1" "--rc-user" "USERNAME" "--rc-pass" "PASSWORD" "."]
2020/03/23 11:36:52 INFO  : Using --user USERNAME --pass XXXX as authenticated user
2020/03/23 11:36:52 NOTICE: Serving files from "."
2020/03/23 11:36:52 NOTICE: Serving remote control on http://127.0.0.1:5572/
2020/03/23 11:36:52 DEBUG : login_token "LOGIN-TOKEN"
2020/03/23 11:36:52 DEBUG : rc: "core/version": with parameters map[]
2020/03/23 11:36:52 DEBUG : rc: "core/version": reply map[arch:amd64 decomposed:1.51.0.125 goVersion:go1.14.1 isGit:false os:windows version:v1.51.0-125-g32df634c-beta]: <nil>
2020/03/23 11:36:52 DEBUG : rc: "config/listremotes": with parameters map[]
2020/03/23 11:36:52 DEBUG : Using config file from "C:\\Users\\USERNAME\\.config\\rclone\\rclone.conf"
2020/03/23 11:36:52 DEBUG : rc: "config/listremotes": reply map[remotes:[onedrive disk]]: <nil>
2020/03/23 11:36:52 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:36:52 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:36:52 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:36:52 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:36:54 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:36:54 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:36:54 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:36:54 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:36:55 DEBUG : rc: "operations/list": with parameters map[fs:onedrive:/path/ remote:to]
2020/03/23 11:36:56 DEBUG : rc: "operations/list": with parameters map[fs:disk:/ remote:]
2020/03/23 11:36:56 DEBUG : rc: "operations/list": reply map[list:[0xc0002232b0 0xc0005425b0 0xc000542750 0xc000542b60 0xc000542c30 0xc000543520 0xc000543ba0 0xc000543c70 0xc000543e10 0xc0000c8000 0xc0000c80d0 0xc0000c81a0]]: <nil>
2020/03/23 11:36:56 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:36:56 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:36:56 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:36:56 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:36:57 DEBUG : rc: "operations/list": with parameters map[fs:disk:/ remote:temp]
2020/03/23 11:36:57 DEBUG : rc: "operations/list": reply map[list:[0xc0002d40d0 0xc0002d41a0 0xc0002d4410 0xc0002d45b0 0xc0002d4680 0xc0002d48f0 0xc0002d49c0 0xc0002d4a90]]: <nil>
2020/03/23 11:36:58 DEBUG : rc: "operations/list": reply map[list:[0xc0000c8b60 0xc0000c8d00 0xc0000c8dd0 0xc0000c8ea0 0xc0000c9040 0xc0000c9110 0xc0000c9380 0xc0000c9450 0xc0000c9520 0xc0000c95f0 0xc0000c96c0 0xc0000c9790 0xc0000c9930 0xc0000c9ad0]]: <nil>
2020/03/23 11:36:58 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:36:58 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:36:58 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:36:58 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:37:00 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:00 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:00 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:37:00 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:37:01 DEBUG : rc: "sync/move": with parameters map[deleteEmptySrcDirs:true dstFs:onedrive:/path/to/some srcFs:disk:/temp/some]
2020/03/23 11:37:02 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:02 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:02 DEBUG : rc: "core/stats": reply map[bytes:0 checks:0 deletes:0 elapsedTime:0 errors:0 fatalError:false retryError:false speed:0 transfers:0]: <nil>
2020/03/23 11:37:02 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:37:03 DEBUG : One drive root 'path/to/some': Waiting for checks to finish
2020/03/23 11:37:03 DEBUG : One drive root 'path/to/some': Waiting for transfers to finish
2020/03/23 11:37:04 DEBUG : singlefile.txt: Starting multipart upload
2020/03/23 11:37:04 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:04 DEBUG : rc: "core/transferred": reply map[transferred:[]]: <nil>
2020/03/23 11:37:04 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:04 DEBUG : rc: "core/stats": reply map[bytes:0 checking:[singlefile.txt] checks:0 deletes:0 elapsedTime:0.9945283 errors:0 fatalError:false retryError:false speed:0 transferring:[map[bytes:0 eta:<nil> group:job/16 name:singlefile.txt percentage:0 size:6 speed:0 speedAvg:0]] transfers:0]: <nil>
2020/03/23 11:37:04 DEBUG : singlefile.txt: Uploading segment 0/6 size 6
2020/03/23 11:37:05 DEBUG : singlefile.txt: SHA-1 = fde773a18bb29f5ed65e6f0a7aa717fd1fa485d4 OK
2020/03/23 11:37:05 INFO  : singlefile.txt: Copied (new)
2020/03/23 11:37:05 INFO  : singlefile.txt: Deleted
2020/03/23 11:37:05 DEBUG : rc: "sync/move": reply map[]: <nil>
2020/03/23 11:37:05 DEBUG : rc: "operations/list": with parameters map[fs:onedrive:/path/ remote:to]
2020/03/23 11:37:05 DEBUG : rc: "operations/list": with parameters map[fs:disk:/ remote:temp]
2020/03/23 11:37:05 DEBUG : rc: "operations/list": reply map[list:[0xc000388270 0xc000388340 0xc000388410 0xc0003884e0 0xc0003885b0 0xc000388680 0xc000388750 0xc000388820]]: <nil>
2020/03/23 11:37:06 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:06 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:06 DEBUG : rc: "core/stats": reply map[bytes:6 checks:2 deletes:1 elapsedTime:1.9970214 errors:0 fatalError:false retryError:false speed:3.0044745639681176 transfers:1]: <nil>
2020/03/23 11:37:06 DEBUG : rc: "core/transferred": reply map[transferred:[{Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:6 Checked:false StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16}]]: <nil>
2020/03/23 11:37:08 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:08 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:08 DEBUG : rc: "core/stats": reply map[bytes:6 checks:2 deletes:1 elapsedTime:1.9970214 errors:0 fatalError:false retryError:false speed:3.0044745639681176 transfers:1]: <nil>
2020/03/23 11:37:08 DEBUG : rc: "core/transferred": reply map[transferred:[{Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:6 Checked:false StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16}]]: <nil>
2020/03/23 11:37:09 DEBUG : rc: "operations/list": reply map[list:[0xc0002fa680 0xc0002fa8f0 0xc0002fa9c0 0xc0002faa90 0xc0002fab60 0xc0002fac30 0xc0002fad00 0xc0002fadd0 0xc0002faea0 0xc0002faf70 0xc0002fb040 0xc0002fb110 0xc0002fb1e0 0xc0002fb2b0 0xc0002fb380]]: <nil>
2020/03/23 11:37:10 DEBUG : rc: "core/transferred": with parameters map[]
2020/03/23 11:37:10 DEBUG : rc: "core/stats": with parameters map[]
2020/03/23 11:37:10 DEBUG : rc: "core/transferred": reply map[transferred:[{Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:6 Checked:false StartedAt:2020-03-23 11:37:03.8104798 +0100 CET m=+11.310740201 CompletedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 Error:<nil> Group:job/16} {Name:singlefile.txt Size:6 Bytes:0 Checked:true StartedAt:2020-03-23 11:37:05.8064989 +0100 CET m=+13.306759301 CompletedAt:2020-03-23 11:37:05.8075012 +0100 CET m=+13.307761601 Error:<nil> Group:job/16}]]: <nil>
2020/03/23 11:37:10 DEBUG : rc: "core/stats": reply map[bytes:6 checks:2 deletes:1 elapsedTime:1.9970214 errors:0 fatalError:false retryError:false speed:3.0044745639681176 transfers:1]: <nil>
2020/03/23 11:37:12 INFO  : Signal received: interrupt
2020/03/23 11:37:12 INFO  : Exiting...

Repeating core/stats and core/transferred are there because I send these queries every 2 seconds to refresh the web GUI.


that is rclone checking it needs to do the transfer before doing it

Sorry for repeating this, but I am still curious, why copy operations (/operations/copyfile and /sync/copy) don't have these checks too? Is that by design?

Thanks for the log.

I think the delete is being counted as a check operation, that is why there are 2 checks and one transfer.

I would expect 1 check and 1 transfer if you try exactly the same thing with copy. I guess if the destination directory doesn't exist then copy won't do the check as it knows it doesn't need to.

I've just tried to copy a directory with one file inside, while the destination also having this directory (but with no contents). The core/transferred request reported only one record - the actual transfer of that file, so there were no records for checks.

I just had a look at the source code... The move is treated as one check the delete the other and the copy the transfer.

For the copy to record a check the file needs to exist at the destination.

Really rclone needs some better stats than just check and transfer! They go with the --checkers and --transfers flags though.

1 Like

Okay, at least I more or less understand what's going on. Thank you for the clarification.

I need it to show user a list of completed transfers without confusing him with duplicate items, so for the time being I will just skip records with "checked": true (and/or maybe with "bytes": 0).

I think that is the correct thing to do.

1 Like

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